18:19:20.329[sip]
18:19:20.329[sip]   ------------------------------------------------------------------------
18:19:20.329[app:dbg]got nua_i_options : 100(Trying)
18:19:20.329[app:dbg]NO CALL IN nua_i_options == 100 : Trying
18:19:20.329[app:dbg]sdp_codecs_init() init call sdp (offer)
18:19:20.329[app:dbg]sdp_codecs_dump() ssup present on, ecan absent on, rfc absent 101, nse absent 0, ptime present 20
18:19:20.339[app:dbg]sdp_codecs_dump() G723: none
18:19:20.339[app:dbg]sdp_codecs_dump() G711A:
18:19:20.339[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
18:19:20.339[app:dbg]sdp_codecs_dump() G711U:
18:19:20.339[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
18:19:20.339[app:dbg]sdp_codecs_g711a_add_to_media_attrs() g711a: have one at last
18:19:20.339[app:dbg]sdp_codecs_g711u_add_to_media_attrs() g711u: have one at last
18:19:20.339[app:dbg]sdp_codecs_rfc2833_add_to_media_attrs() absent, pt 101
18:19:20.339[app:dbg]sdp_codecs_nse_add_to_media_attrs() absent, pt 0
18:19:20.339[app:dbg]sdp_codecs_ptime_add_to_attrs() ptime present 20
18:19:20.339[app:dbg]sdp_codecs_ecan_add_to_attrs() ecan absent on
18:19:20.339[app:dbg]sdp_codecs_ssup_add_to_attrs() ssup present on
18:19:20.339[app:dbg]sdp_tail:  8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
a=silenceSupp:on - - - -
18:19:20.339[app:dbg]make_sdp: SDP: s=Session SDP
m=audio 0 RTP/AVP 8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
a=silenceSupp:on - - - -
18:19:20.339[sip]send 824 bytes to udp/[192.168.100.90]:5060 at 01:49:56.120000:
18:19:20.339[sip]   ------------------------------------------------------------------------
18:19:20.339[sip]   SIP/2.0 200 OK
18:19:20.339[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK21d62144
18:19:20.339[sip]   From: "Unknown" <sip:Unknown@192.168.100.90>;tag=as2d3b05fb
18:19:20.339[sip]   To: <sip:1101@192.168.100.91:5060>;tag=HBHB6D70N0yaB
18:19:20.339[sip]   Call-ID: 0bd91faf1321f7912a406e3a180e0792@192.168.100.90:5060
18:19:20.339[sip]   CSeq: 102 OPTIONS
18:19:20.339[sip]   Contact: <sip:1101@192.168.100.91:5060>
18:19:20.339[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:19:20.339[sip]   Accept: application/sdp
18:19:20.339[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:19:20.339[sip]   Supported: timer, 100rel, replaces
18:19:20.339[sip]   Content-Type: application/sdp
18:19:20.339[sip]   Content-Length: 236
18:19:20.339[sip]
18:19:20.339[sip]   v=0
18:19:20.339[sip]   o=- 4510163741362109568 5583644925016200430 IN IP4 192.168.100.91
18:19:20.339[sip]   s=Session SDP
18:19:20.339[sip]   c=IN IP4 192.168.100.91
18:19:20.339[sip]   t=0 0
18:19:20.339[sip]   m=audio 0 RTP/AVP 8 0
18:19:20.339[sip]   a=rtpmap:8 PCMA/8000
18:19:20.339[sip]   a=rtpmap:0 PCMU/8000
18:19:20.339[sip]   a=inactive
18:19:20.339[sip]   a=ptime:20
18:19:20.339[sip]   a=silenceSupp:on - - - -
18:19:20.339[sip]   ------------------------------------------------------------------------
18:19:20.339[app:dbg]== current tester cb ==self_i_outbound=============================
18:19:20.339[app:ERR]self_i_outbound() no call
18:19:20.939[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:19:20.939[app:dbg]vapi: tone detect: Conn 7. Detect signal <DTMF digit 1> (level 7 dBov)
18:19:20.949[app:dbg]hio: port 7: digit 1 (code 0x11), tone
18:19:20.949[app:info]SLIC 7: from state 'hangdown' to state 'dial'
18:19:20.949[app:dbg]CMD_STOP_TONE: port = 7
18:19:20.949[app:dbg]Port 7: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:19:20.949[app:dbg]Chan 7: current state is CREATED
18:19:20.949[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1520
18:19:20.949[app:dbg]VQ Conn 7 = MSP :     'stop_tone' =
18:19:20.949[app:dbg]chan 7 stop tone
18:19:20.949[app:dbg]Port 7: user port 1, old state dial, new state
18:19:20.949[app:dbg]Set port 7 led to state 'LED_ON'
18:19:20.949[app:dbg]pbx -[msg_fxs_state]-> group
18:19:20.949[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000923
18:19:20.949[app:dbg]ITC: [msg_fxs_state] -> group
18:19:20.949[app:dbg]-----[GM] self_fxs_state()
18:19:20.949[app:dbg]Port 7: new state is dial
18:19:20.969[app:dbg]first !* and !# - can`t be dvo
18:19:20.969[app:info]SLIC 7: digit 1
18:19:20.969[app:dbg]check item 0: 0x0FFF/080000FF,0 : <1>
18:19:20.969[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0xFFF
18:19:20.969[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:19:20.969[app:dbg]match ok: rf 0, crt 1, rt 255
18:19:20.969[app:dbg]end of items - test dial ended
18:19:20.969[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 1, r{0,255(inf)}
18:19:20.969[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:19:20.969[app:dbg]check item 0: 0x03FF/080000FF,0 : <1>
18:19:20.969[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0x3FF
18:19:20.969[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:19:20.969[app:dbg]match ok: rf 0, crt 1, rt 255
18:19:20.969[app:dbg]end of items - test dial ended
18:19:20.969[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 1, r{0,255(inf)}
18:19:20.969[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:19:20.969[app:dbg]check item 0: 0x0800/00000000,0 : <1>
18:19:20.969[app:dbg]regex_match_item: check route 0x304c18 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x800
18:19:20.969[app:dbg]regex_match_item: digit '1' not in mask[0] 0x0800
18:19:20.969[app:dbg]<whole not match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:20.969[app:dbg]match fail
18:19:20.969[app:dbg]check item 0: 0x0800/04000000,0 : <1>
18:19:20.969[app:dbg]regex_match_item: check route 0x304ac0 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x800
18:19:20.969[app:dbg]regex_match_item: digit '1' not in mask[0] 0x0800
18:19:20.969[app:dbg]<whole not match>: dial <1>r 0, dt 1, sub 0 {0,0}
18:19:20.969[app:dbg]match fail
18:19:20.969[app:dbg]check item 0: 0x0400/00000000,0 : <1>
18:19:20.969[app:dbg]regex_match_item: check route 0x304968 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x400
18:19:20.969[app:dbg]regex_match_item: digit '1' not in mask[0] 0x0400
18:19:20.969[app:dbg]<whole not match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:20.969[app:dbg]match fail
18:19:20.969[app:dbg]check item 0: 0x03FC/00000000,0 : <1>
18:19:20.969[app:dbg]regex_match_item: check route 0x304810 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FC
18:19:20.969[app:dbg]regex_match_item: digit '1' not in mask[0] 0x03FC
18:19:20.969[app:dbg]<whole not match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:20.969[app:dbg]match fail
18:19:20.969[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:19:20.969[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:20.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:20.969[app:dbg]check item 1: 0x03FF/00000000,0 : <F>
18:19:20.969[app:dbg]check 'cant dial more' within cycle: item 0, crt 0, {0,0}
18:19:20.969[app:dbg]MATCH: fulldialed 0, can`t dial more 0, dialtone 0 fullmatch 0
18:19:20.969[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:19:20.969[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:20.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:20.969[app:dbg]check item 1: 0x03FF/00000000,0 : <F>
18:19:20.969[app:dbg]check 'cant dial more' within cycle: item 0, crt 0, {0,0}
18:19:20.969[app:dbg]MATCH: fulldialed 0, can`t dial more 0, dialtone 0 fullmatch 0
18:19:20.969[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:19:20.969[app:dbg]regex_match_item: check route 0x304408 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:20.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:20.969[app:dbg]check item 1: 0x03FF/00000000,0 : <F>
18:19:20.969[app:dbg]check 'cant dial more' within cycle: item 0, crt 0, {0,0}
18:19:20.969[app:dbg]MATCH: fulldialed 0, can`t dial more 0, dialtone 0 fullmatch 0
18:19:20.969[app:dbg]check item 0: 0x0100/00000000,0 : <1>
18:19:20.969[app:dbg]regex_match_item: check route 0x3042b0 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x100
18:19:20.969[app:dbg]regex_match_item: digit '1' not in mask[0] 0x0100
18:19:20.969[app:dbg]<whole not match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:20.969[app:dbg]match fail
18:19:20.969[app:dbg]check item 0: 0x03FC/00000000,0 : <1>
18:19:20.969[app:dbg]regex_match_item: check route 0x304158 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FC
18:19:20.969[app:dbg]regex_match_item: digit '1' not in mask[0] 0x03FC
18:19:20.969[app:dbg]<whole not match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:20.969[app:dbg]match fail
18:19:20.969[app:dbg]check item 0: 0x0100/00000000,0 : <1>
18:19:20.969[app:dbg]regex_match_item: check route 0x304000 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x100
18:19:20.969[app:dbg]regex_match_item: digit '1' not in mask[0] 0x0100
18:19:20.969[app:dbg]<whole not match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:20.969[app:dbg]match fail
18:19:20.969[app:dbg]07: [3,4,5,10,11,]
18:19:20.969[app:dbg]port_process_digit() regex route 0x304ec8, final 1, dt 0
18:19:20.969[app:dbg]port 7: process final route
18:19:20.989[app:dbg]vapi_proc_event: VAPI_CB
18:19:20.989[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000923 result 0x00000000
18:19:20.989[app:dbg]Conn 7: Stop tone - Successfull
18:19:20.989[app:dbg]Port 7: check vapi queue ('busy''stop_tone') at vapi_next_ops:2532
18:19:20.999[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 7
18:19:21.019[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:19:21.019[app:dbg]vapi: tone detect: Conn 7. End of signal <DTMF digit 1>, duration 90 ms
18:19:21.029[app:dbg]port 7: regex per sec timeout
18:19:21.299[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:19:21.299[app:dbg]vapi: tone detect: Conn 7. Detect signal <DTMF digit 1> (level 7 dBov)
18:19:21.309[app:dbg]hio: port 7: digit 1 (code 0x11), tone
18:19:21.309[app:info]SLIC 7: digit 1
18:19:21.309[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:19:21.309[app:dbg]regex_match_item: check route 0x304408 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:21.309[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:21.309[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:19:21.309[app:dbg]regex_match_item: check route 0x304408 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:21.309[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:21.309[app:dbg]end of items - test dial ended
18:19:21.309[app:dbg]check 'cant dial more' out of the cycle: item 1, crt 0, {0,0}
18:19:21.309[app:dbg]MATCH: fulldialed 1, can`t dial more 1, dialtone 0 fullmatch 1
18:19:21.309[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:19:21.309[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:21.309[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:21.309[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:19:21.309[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:21.309[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:21.309[app:dbg]check item 2: 0x03FF/00000000,0 : <F>
18:19:21.309[app:dbg]check 'cant dial more' within cycle: item 1, crt 0, {0,0}
18:19:21.309[app:dbg]MATCH: fulldialed 0, can`t dial more 0, dialtone 0 fullmatch 0
18:19:21.309[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:19:21.309[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:21.309[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:21.309[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:19:21.309[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:21.309[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:21.309[app:dbg]check item 2: 0x03FF/00000000,0 : <F>
18:19:21.309[app:dbg]check 'cant dial more' within cycle: item 1, crt 0, {0,0}
18:19:21.309[app:dbg]MATCH: fulldialed 0, can`t dial more 0, dialtone 0 fullmatch 0
18:19:21.309[app:dbg]check item 0: 0x03FF/080000FF,0 : <1>
18:19:21.309[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0x3FF
18:19:21.309[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:19:21.309[app:dbg]match ok: rf 0, crt 1, rt 255
18:19:21.309[app:dbg]check item 0: 0x03FF/080000FF,1 : <1>
18:19:21.309[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 1, digit '1' mask 0x3FF
18:19:21.309[app:dbg]<cur match>: dial <1>r 2, dt 0, sub 0 r{0,255(inf)}
18:19:21.309[app:dbg]match ok: rf 0, crt 2, rt 255
18:19:21.309[app:dbg]end of items - test dial ended
18:19:21.309[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 2, r{0,255(inf)}
18:19:21.309[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:19:21.309[app:dbg]check item 0: 0x0FFF/080000FF,0 : <1>
18:19:21.309[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0xFFF
18:19:21.309[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:19:21.309[app:dbg]match ok: rf 0, crt 1, rt 255
18:19:21.309[app:dbg]check item 0: 0x0FFF/080000FF,1 : <1>
18:19:21.309[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 1, digit '1' mask 0xFFF
18:19:21.309[app:dbg]<cur match>: dial <1>r 2, dt 0, sub 0 r{0,255(inf)}
18:19:21.309[app:dbg]match ok: rf 0, crt 2, rt 255
18:19:21.309[app:dbg]end of items - test dial ended
18:19:21.309[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 2, r{0,255(inf)}
18:19:21.309[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:19:21.309[app:dbg]07: [3,4,5,10,11,]
18:19:21.309[app:dbg]port_process_digit() regex route 0x304408, final 1, dt 0
18:19:21.309[app:dbg]port 7: process final route
18:19:21.379[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:19:21.379[app:dbg]vapi: tone detect: Conn 7. End of signal <DTMF digit 1>, duration 90 ms
18:19:21.959[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:19:21.959[app:dbg]vapi: tone detect: Conn 7. Detect signal <DTMF digit 0> (level 7 dBov)
18:19:21.969[app:dbg]hio: port 7: digit 0 (code 0x10), tone
18:19:21.969[app:dbg]no matched dvo for 110
18:19:21.969[app:info]SLIC 7: digit 0
18:19:21.969[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:19:21.969[app:dbg]regex_match_item: check route 0x304408 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:21.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:21.969[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:19:21.969[app:dbg]regex_match_item: check route 0x304408 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:21.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:21.969[app:dbg]end of items - test dial ended
18:19:21.969[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:19:21.969[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:21.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:21.969[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:19:21.969[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:21.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:21.969[app:dbg]check item 2: 0x03FF/00000000,0 : <0>
18:19:21.969[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '0' mask 0x3FF
18:19:21.969[app:dbg]<cur match>: dial <0>r 0, dt 0, sub 0 {0,0}
18:19:21.969[app:dbg]end of items - test dial ended
18:19:21.969[app:dbg]check 'cant dial more' out of the cycle: item 2, crt 0, {0,0}
18:19:21.969[app:dbg]MATCH: fulldialed 1, can`t dial more 1, dialtone 0 fullmatch 1
18:19:21.969[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:19:21.969[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:21.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:21.969[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:19:21.969[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:21.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:21.969[app:dbg]check item 2: 0x03FF/00000000,0 : <0>
18:19:21.969[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '0' mask 0x3FF
18:19:21.969[app:dbg]<cur match>: dial <0>r 0, dt 0, sub 0 {0,0}
18:19:21.969[app:dbg]check item 3: 0x03FF/080000FF,0 : <F>
18:19:21.969[app:dbg]check 'cant dial more' within cycle: item 2, crt 0, {0,0}
18:19:21.969[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 0
18:19:21.969[app:dbg]check item 0: 0x03FF/080000FF,0 : <1>
18:19:21.969[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0x3FF
18:19:21.969[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:19:21.969[app:dbg]match ok: rf 0, crt 1, rt 255
18:19:21.969[app:dbg]check item 0: 0x03FF/080000FF,1 : <1>
18:19:21.969[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 1, digit '1' mask 0x3FF
18:19:21.969[app:dbg]<cur match>: dial <1>r 2, dt 0, sub 0 r{0,255(inf)}
18:19:21.969[app:dbg]match ok: rf 0, crt 2, rt 255
18:19:21.969[app:dbg]check item 0: 0x03FF/080000FF,2 : <0>
18:19:21.969[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 2, digit '0' mask 0x3FF
18:19:21.969[app:dbg]<cur match>: dial <0>r 3, dt 0, sub 0 r{0,255(inf)}
18:19:21.969[app:dbg]match ok: rf 0, crt 3, rt 255
18:19:21.969[app:dbg]end of items - test dial ended
18:19:21.969[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 3, r{0,255(inf)}
18:19:21.969[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:19:21.969[app:dbg]check item 0: 0x0FFF/080000FF,0 : <1>
18:19:21.969[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0xFFF
18:19:21.969[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:19:21.969[app:dbg]match ok: rf 0, crt 1, rt 255
18:19:21.969[app:dbg]check item 0: 0x0FFF/080000FF,1 : <1>
18:19:21.969[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 1, digit '1' mask 0xFFF
18:19:21.969[app:dbg]<cur match>: dial <1>r 2, dt 0, sub 0 r{0,255(inf)}
18:19:21.969[app:dbg]match ok: rf 0, crt 2, rt 255
18:19:21.969[app:dbg]check item 0: 0x0FFF/080000FF,2 : <0>
18:19:21.969[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 2, digit '0' mask 0xFFF
18:19:21.969[app:dbg]<cur match>: dial <0>r 3, dt 0, sub 0 r{0,255(inf)}
18:19:21.969[app:dbg]match ok: rf 0, crt 3, rt 255
18:19:21.969[app:dbg]end of items - test dial ended
18:19:21.969[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 3, r{0,255(inf)}
18:19:21.969[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:19:21.969[app:dbg]07: [4,5,10,11,]
18:19:21.969[app:dbg]port_process_digit() regex route 0x304560, final 1, dt 0
18:19:21.969[app:dbg]port 7: process final route
18:19:22.039[app:dbg]port 7: regex per sec timeout
18:19:22.039[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:19:22.039[app:dbg]vapi: tone detect: Conn 7. End of signal <DTMF digit 0>, duration 90 ms
18:19:22.659[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:19:22.659[app:dbg]vapi: tone detect: Conn 7. Detect signal <DTMF digit 2> (level 6 dBov)
18:19:22.669[app:dbg]hio: port 7: digit 2 (code 0x12), tone
18:19:22.669[app:dbg]no matched dvo for 1102
18:19:22.669[app:info]SLIC 7: digit 2
18:19:22.669[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:19:22.669[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:22.669[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:22.669[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:19:22.669[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:22.669[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:22.669[app:dbg]check item 2: 0x03FF/00000000,0 : <0>
18:19:22.669[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '0' mask 0x3FF
18:19:22.669[app:dbg]<cur match>: dial <0>r 0, dt 0, sub 0 {0,0}
18:19:22.669[app:dbg]end of items - test dial ended
18:19:22.669[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:19:22.669[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:22.669[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:22.669[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:19:22.669[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:19:22.669[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:19:22.669[app:dbg]check item 2: 0x03FF/00000000,0 : <0>
18:19:22.669[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '0' mask 0x3FF
18:19:22.669[app:dbg]<cur match>: dial <0>r 0, dt 0, sub 0 {0,0}
18:19:22.669[app:dbg]check item 3: 0x03FF/080000FF,0 : <2>
18:19:22.669[app:dbg]regex_match_item: check route 0x3046b8 repeat on rf 0, rt 255(inf), crt 0, digit '2' mask 0x3FF
18:19:22.669[app:dbg]<cur match>: dial <2>r 1, dt 0, sub 0 r{0,255(inf)}
18:19:22.669[app:dbg]match ok: rf 0, crt 1, rt 255
18:19:22.669[app:dbg]end of items - test dial ended
18:19:22.669[app:dbg]check 'cant dial more' out of the cycle: item 3, crt 1, r{0,255(inf)}
18:19:22.669[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:19:22.669[app:dbg]check item 0: 0x03FF/080000FF,0 : <1>
18:19:22.669[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0x3FF
18:19:22.669[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:19:22.669[app:dbg]match ok: rf 0, crt 1, rt 255
18:19:22.669[app:dbg]check item 0: 0x03FF/080000FF,1 : <1>
18:19:22.669[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 1, digit '1' mask 0x3FF
18:19:22.669[app:dbg]<cur match>: dial <1>r 2, dt 0, sub 0 r{0,255(inf)}
18:19:22.669[app:dbg]match ok: rf 0, crt 2, rt 255
18:19:22.669[app:dbg]check item 0: 0x03FF/080000FF,2 : <0>
18:19:22.669[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 2, digit '0' mask 0x3FF
18:19:22.669[app:dbg]<cur match>: dial <0>r 3, dt 0, sub 0 r{0,255(inf)}
18:19:22.669[app:dbg]match ok: rf 0, crt 3, rt 255
18:19:22.669[app:dbg]check item 0: 0x03FF/080000FF,3 : <2>
18:19:22.669[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 3, digit '2' mask 0x3FF
18:19:22.669[app:dbg]<cur match>: dial <2>r 4, dt 0, sub 0 r{0,255(inf)}
18:19:22.669[app:dbg]match ok: rf 0, crt 4, rt 255
18:19:22.669[app:dbg]end of items - test dial ended
18:19:22.669[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 4, r{0,255(inf)}
18:19:22.669[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:19:22.669[app:dbg]check item 0: 0x0FFF/080000FF,0 : <1>
18:19:22.669[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0xFFF
18:19:22.669[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:19:22.669[app:dbg]match ok: rf 0, crt 1, rt 255
18:19:22.669[app:dbg]check item 0: 0x0FFF/080000FF,1 : <1>
18:19:22.669[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 1, digit '1' mask 0xFFF
18:19:22.669[app:dbg]<cur match>: dial <1>r 2, dt 0, sub 0 r{0,255(inf)}
18:19:22.669[app:dbg]match ok: rf 0, crt 2, rt 255
18:19:22.669[app:dbg]check item 0: 0x0FFF/080000FF,2 : <0>
18:19:22.669[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 2, digit '0' mask 0xFFF
18:19:22.669[app:dbg]<cur match>: dial <0>r 3, dt 0, sub 0 r{0,255(inf)}
18:19:22.669[app:dbg]match ok: rf 0, crt 3, rt 255
18:19:22.669[app:dbg]check item 0: 0x0FFF/080000FF,3 : <2>
18:19:22.669[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 3, digit '2' mask 0xFFF
18:19:22.669[app:dbg]<cur match>: dial <2>r 4, dt 0, sub 0 r{0,255(inf)}
18:19:22.669[app:dbg]match ok: rf 0, crt 4, rt 255
18:19:22.669[app:dbg]end of items - test dial ended
18:19:22.669[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 4, r{0,255(inf)}
18:19:22.669[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:19:22.669[app:dbg]07: [5,10,11,]
18:19:22.669[app:dbg]port_process_digit() regex route 0x3046b8, final 1, dt 0
18:19:22.669[app:dbg]port 7: process final route
18:19:22.739[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:19:22.739[app:dbg]vapi: tone detect: Conn 7. End of signal <DTMF digit 2>, duration 90 ms
18:19:23.019[app:dbg]port 7: regex per sec timeout
18:19:24.039[app:dbg]port 7: regex per sec timeout
18:19:25.029[app:dbg]port 7: regex per sec timeout
18:19:26.019[app:dbg]port 7: regex per sec timeout
18:19:27.039[app:dbg]port 7: regex per sec timeout
18:19:27.039[app:dbg]SLIC 7: final action
18:19:27.039[app:info]SLIC 7: dial <1102>
18:19:27.039[app:dbg]pbx: allocating memory for new call
18:19:27.039[app:dbg]pbx: created new outgoing call for SLIC 7
18:19:27.039[app:dbg]self_call_create (4455): created
18:19:27.039[app:dbg]free_final_mx: final_mx was NULL for SLIC 7
18:19:27.039[app:dbg]SLIC 7: -> calling to sip//1102
18:19:27.039[app:dbg]ext: 0
18:19:27.039[app:dbg]pbx -[msg_call]-> sip
18:19:27.039[app:dbg]ITC: [msg_call] -> sip
18:19:27.039[app:dbg]sip: outgoing call 00070025 from endpoint 7 to 1102@(null)
18:19:27.039[app:dbg]available RTP ports: 23000...26000
18:19:27.039[app:dbg]selected port for current call: 23440
18:19:27.039[app:dbg]sip_params_create() normal - using cur proxy [192.168.100.90] if proxy call
18:19:27.039[app:dbg]stun_get_public_ip(port = 8000)
18:19:27.039[app:dbg]stun_get_public_ip: Always using local IP
18:19:27.039[app:dbg]sip: to host is <(null)> - should not have port; to user is <1102>, use proxy - yes
18:19:27.039[app:dbg]sip_params_create() send to is <sip:1102@192.168.100.90>, <not outbound>
18:19:27.039[app:dbg]sip_params_create() target,request url is <sip:1102@192.168.100.90>
18:19:27.039[app:dbg]sip: call 00070025: sip  INVITE from sip:1101@192.168.100.90 to sip:1102@192.168.100.90
18:19:27.039[app:dbg]sip: call 00070025: targeturl is <sip:1102@192.168.100.90>
18:19:27.039[app:dbg]build contact field with To-Host '192.168.100.90'
18:19:27.039[app:dbg]stun_get_public_ip(port = 5060)
18:19:27.039[app:dbg]stun_get_public_ip: Always using local IP
18:19:27.039[app:dbg]stun_get_public_ip(port = 23440)
18:19:27.039[app:dbg]stun_get_public_ip: Always using local IP
18:19:27.039[app:dbg]sdp_codecs_init() init call sdp (offer)
18:19:27.039[app:dbg]sdp_codecs_dump() ssup present on, ecan absent on, rfc absent 101, nse absent 0, ptime present 20
18:19:27.039[app:dbg]sdp_codecs_dump() G723: none
18:19:27.039[app:dbg]sdp_codecs_dump() G711A:
18:19:27.039[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
18:19:27.039[app:dbg]sdp_codecs_dump() G711U:
18:19:27.039[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
18:19:27.039[app:dbg]sdp_codecs_g711a_add_to_media_attrs() g711a: have one at last
18:19:27.039[app:dbg]sdp_codecs_g711u_add_to_media_attrs() g711u: have one at last
18:19:27.039[app:dbg]sdp_codecs_rfc2833_add_to_media_attrs() absent, pt 101
18:19:27.039[app:dbg]sdp_codecs_nse_add_to_media_attrs() absent, pt 0
18:19:27.039[app:dbg]sdp_codecs_ptime_add_to_attrs() ptime present 20
18:19:27.039[app:dbg]sdp_codecs_ecan_add_to_attrs() ecan absent on
18:19:27.039[app:dbg]sdp_codecs_ssup_add_to_attrs() ssup present on
18:19:27.039[app:dbg]sdp_tail:  8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
a=silenceSupp:on - - - -
18:19:27.039[app:dbg]make_sdp: SDP: s=Session SDP
m=audio 23440 RTP/AVP 8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
a=silenceSupp:on - - - -
18:19:27.039[app:dbg]sip: get_support_params: profile 2 supported: 'timer, 100rel, replaces'
18:19:27.049[app:dbg]got nua_r_set_params : 200(OK)
18:19:27.049[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
18:19:27.049[app:info]SLIC 7: from state 'dial' to state 'calling'
18:19:27.049[app:dbg]CMD_STOP_TONE: port = 7
18:19:27.049[app:dbg]Port 7: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:19:27.049[app:dbg]Chan 7: current state is CREATED
18:19:27.049[app:ERR]chan 7: no generated tones!
18:19:27.049[app:dbg]vapi_chan.c:1510: conn 7 peek cmd 'no event' from queue
18:19:27.049[app:dbg]Port 7: check vapi queue ('free') at __cmd_engine:320
18:19:27.049[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2532
18:19:27.049[app:dbg]Port 7: user port 1, old state calling, new state
18:19:27.049[sip]send 863 bytes to udp/[192.168.100.90]:5060 at 01:50:02.830000:
18:19:27.049[sip]   ------------------------------------------------------------------------
18:19:27.049[sip]   INVITE sip:1102@192.168.100.90 SIP/2.0
18:19:27.049[sip]   Via: SIP/2.0/UDP 192.168.100.91;rport;branch=z9hG4bKyNS83jtBgerSj
18:19:27.049[sip]   Max-Forwards: 70
18:19:27.049[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=jma478Q4j9mXp
18:19:27.049[sip]   To: <sip:1102@192.168.100.90>
18:19:27.049[sip]   Call-ID: a28f2431-8002-1234-0a8d-a8f94b09c764
18:19:27.049[sip]   CSeq: 3301 INVITE
18:19:27.049[sip]   Contact: <sip:1101@192.168.100.91:5060>
18:19:27.049[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:19:27.049[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:19:27.049[sip]   Supported: timer, 100rel, replaces
18:19:27.049[sip]   Session-Expires: 1800
18:19:27.049[sip]   Min-SE: 120
18:19:27.049[sip]   Content-Type: application/sdp
18:19:27.049[sip]   Content-Disposition: session
18:19:27.049[sip]   Content-Length: 228
18:19:27.049[sip]
18:19:27.049[sip]   v=0
18:19:27.049[sip]   o=- 8119781622165824633 1486187085433260004 IN IP4 192.168.100.91
18:19:27.049[sip]   s=Session SDP
18:19:27.049[sip]   c=IN IP4 192.168.100.91
18:19:27.049[sip]   t=0 0
18:19:27.049[sip]   m=audio 23440 RTP/AVP 8 0
18:19:27.049[sip]   a=rtpmap:8 PCMA/8000
18:19:27.049[sip]   a=rtpmap:0 PCMU/8000
18:19:27.049[sip]   a=ptime:20
18:19:27.049[sip]   a=silenceSupp:on - - - -
18:19:27.049[sip]   ------------------------------------------------------------------------
18:19:27.049[sip]recv 540 bytes from udp/[192.168.100.90]:5060 at 01:50:02.830000:
18:19:27.049[sip]   ------------------------------------------------------------------------
18:19:27.049[sip]   SIP/2.0 401 Unauthorized
18:19:27.049[sip]   Via: SIP/2.0/UDP 192.168.100.91;branch=z9hG4bKyNS83jtBgerSj;received=192.168.100.91;rport=5060
18:19:27.049[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=jma478Q4j9mXp
18:19:27.049[sip]   To: <sip:1102@192.168.100.90>;tag=as5797e732
18:19:27.059[app:dbg]got nua_i_state : 0(INVITE sent)
18:19:27.059[app:dbg]NO SIP IN nua_i_state == 0 : INVITE sent
18:19:27.059[app:dbg]self_i_state(): call state 2: os : local sdp : sdp_init no_oc
18:19:27.059[app:dbg]sip: call 00070025: SDP offer sent
18:19:27.059[app:dbg]self_create_local_media() 0: add rtpmap 8
18:19:27.059[app:dbg]self_create_local_media() 1: add rtpmap 0
18:19:27.059[app:dbg]sip: call 00070025: media stream 0, creating proposed audio channel, local RTP 192.168.100.91:23440, rtpmaps cnt: 2
18:19:27.059[app:dbg]sip: call 00070025: local SDP offer copy
18:19:27.059[app:dbg]Set port 7 led to state 'LED_ON'
18:19:27.059[app:dbg]pbx -[msg_fxs_state]-> group
18:19:27.059[app:dbg]ITC: [msg_fxs_state] -> group
18:19:27.059[app:dbg]-----[GM] self_fxs_state()
18:19:27.059[app:dbg]Port 7: new state is calling
18:19:27.059[sip]   Call-ID: a28f2431-8002-1234-0a8d-a8f94b09c764
18:19:27.059[sip]   CSeq: 3301 INVITE
18:19:27.059[sip]   Server: FPBX-13.0.101(13.8.0)
18:19:27.059[sip]   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
18:19:27.059[sip]   Supported: replaces, timer
18:19:27.059[sip]   WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="1c5be4af"
18:19:27.059[sip]   Content-Length: 0
18:19:27.059[sip]
18:19:27.059[sip]   ------------------------------------------------------------------------
18:19:27.059[sip]send 310 bytes to udp/[192.168.100.90]:5060 at 01:50:02.840000:
18:19:27.059[sip]   ------------------------------------------------------------------------
18:19:27.059[sip]   ACK sip:1102@192.168.100.90 SIP/2.0
18:19:27.059[sip]   Via: SIP/2.0/UDP 192.168.100.91;rport;branch=z9hG4bKyNS83jtBgerSj
18:19:27.059[sip]   Max-Forwards: 70
18:19:27.059[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=jma478Q4j9mXp
18:19:27.059[sip]   To: <sip:1102@192.168.100.90>;tag=as5797e732
18:19:27.059[sip]   Call-ID: a28f2431-8002-1234-0a8d-a8f94b09c764
18:19:27.059[sip]   CSeq: 3301 ACK
18:19:27.059[sip]   Content-Length: 0
18:19:27.059[sip]
18:19:27.059[sip]   ------------------------------------------------------------------------
18:19:27.059[app:dbg]got nua_r_invite : 401(Unauthorized)
18:19:27.059[app:dbg]sip: call 00070025: INVITE: 401 Unauthorized
18:19:27.079[app:dbg]sip: call 00070025: trying to authenticate INVITE
18:19:27.079[app:dbg]auth mode is USER
18:19:27.079[sip]send 1029 bytes to udp/[192.168.100.90]:5060 at 01:50:02.860000:
18:19:27.079[sip]   ------------------------------------------------------------------------
18:19:27.079[sip]   INVITE sip:1102@192.168.100.90 SIP/2.0
18:19:27.079[sip]   Via: SIP/2.0/UDP 192.168.100.91;rport;branch=z9hG4bKZyj15DBFDQece
18:19:27.079[sip]   Max-Forwards: 70
18:19:27.079[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=jma478Q4j9mXp
18:19:27.079[sip]   To: <sip:1102@192.168.100.90>
18:19:27.079[sip]   Call-ID: a28f2431-8002-1234-0a8d-a8f94b09c764
18:19:27.079[sip]   CSeq: 3302 INVITE
18:19:27.079[sip]   Contact: <sip:1101@192.168.100.91:5060>
18:19:27.079[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:19:27.079[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:19:27.079[sip]   Supported: timer, 100rel, replaces
18:19:27.079[sip]   Authorization: Digest username="1101", realm="asterisk", nonce="1c5be4af", algorithm=MD5, uri="sip:1102@192.168.100.90", response="fb2b9b7dc6638e8e2ed43799fd4136c5"
18:19:27.079[sip]   Session-Expires: 1800
18:19:27.079[sip]   Min-SE: 120
18:19:27.079[sip]   Content-Type: application/sdp
18:19:27.079[sip]   Content-Disposition: session
18:19:27.079[sip]   Content-Length: 228
18:19:27.079[sip]
18:19:27.079[sip]   v=0
18:19:27.079[sip]   o=- 8119781622165824633 1486187085433260004 IN IP4 192.168.100.91
18:19:27.079[sip]   s=Session SDP
18:19:27.079[sip]   c=IN IP4 192.168.100.91
18:19:27.079[sip]   t=0 0
18:19:27.079[sip]   m=audio 23440 RTP/AVP 8 0
18:19:27.079[sip]   a=rtpmap:8 PCMA/8000
18:19:27.079[sip]   a=rtpmap:0 PCMU/8000
18:19:27.079[sip]   a=ptime:20
18:19:27.079[sip]   a=silenceSupp:on - - - -
18:19:27.079[sip]   ------------------------------------------------------------------------
18:19:27.079[sip]recv 521 bytes from udp/[192.168.100.90]:5060 at 01:50:02.860000:
18:19:27.079[sip]   ------------------------------------------------------------------------
18:19:27.079[sip]   SIP/2.0 100 Trying
18:19:27.079[sip]   Via: SIP/2.0/UDP 192.168.100.91;branch=z9hG4bKZyj15DBFDQece;received=192.168.100.91;rport=5060
18:19:27.079[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=jma478Q4j9mXp
18:19:27.079[sip]   To: <sip:1102@192.168.100.90>
18:19:27.089[sip]   Call-ID: a28f2431-8002-1234-0a8d-a8f94b09c764
18:19:27.089[sip]   CSeq: 3302 INVITE
18:19:27.089[sip]   Server: FPBX-13.0.101(13.8.0)
18:19:27.089[sip]   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
18:19:27.089[sip]   Supported: replaces, timer
18:19:27.089[sip]   Session-Expires: 1800;refresher=uas
18:19:27.089[sip]   Contact: <sip:1102@192.168.100.90:5060>
18:19:27.089[sip]   Content-Length: 0
18:19:27.089[sip]
18:19:27.089[sip]   ------------------------------------------------------------------------
18:19:27.089[app:dbg]got nua_i_state : 0(INVITE sent)
18:19:27.099[app:dbg]NO SIP IN nua_i_state == 0 : INVITE sent
18:19:27.099[app:dbg]self_i_state(): call state 2: os : local sdp : sdp_sent have_oc
18:19:27.089[app:dbg]regex ID 7: dial reset
18:19:27.099[app:dbg]got nua_r_invite : 100(Trying)
18:19:27.099[app:dbg]sip: call 00070025: INVITE: 100 Trying
18:19:27.099[app:dbg]Contact/Record-route on answer to INVITE: sip:1102@192.168.100.90:5060
18:19:27.099[app:dbg]Setup new proxy addr for call; sip:1102@192.168.100.90:5060
18:19:27.099[app:dbg]call 00458789 got 100/Trying - set received_1xx
18:19:27.099[app:dbg]got nua_r_set_params : 200(OK)
18:19:27.099[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
18:19:27.259[sip]recv 914 bytes from udp/[192.168.100.90]:5060 at 01:50:03.040000:
18:19:27.259[sip]   ------------------------------------------------------------------------
18:19:27.259[sip]   INVITE sip:1102@192.168.100.91:5060 SIP/2.0
18:19:27.259[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK173db2de
18:19:27.259[sip]   Max-Forwards: 70
18:19:27.259[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=as60c1a347
18:19:27.259[sip]   To: <sip:1102@192.168.100.91:5060>
18:19:27.259[sip]   Contact: <sip:1101@192.168.100.90:5060>
18:19:27.259[sip]   Call-ID: 4979b03056b6a00277558ec17742ce4f@192.168.100.90:5060
18:19:27.259[sip]   CSeq: 102 INVITE
18:19:27.259[sip]   User-Agent: FPBX-13.0.101(13.8.0)
18:19:27.259[sip]   Date: Mon, 18 Apr 2016 12:19:16 GMT
18:19:27.259[sip]   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
18:19:27.259[sip]   Supported: replaces, timer
18:19:27.259[sip]   Content-Type: application/sdp
18:19:27.259[sip]   Content-Length: 331
18:19:27.259[sip]
18:19:27.259[sip]   v=0
18:19:27.259[sip]   o=root 451562368 451562368 IN IP4 192.168.100.90
18:19:27.259[sip]   s=Asterisk PBX 13.8.0
18:19:27.259[sip]   c=IN IP4 192.168.100.90
18:19:27.259[sip]   t=0 0
18:19:27.259[sip]   m=audio 18400 RTP/AVP 0 8 3 111 101
18:19:27.259[sip]   a=rtpmap:0 PCMU/8000
18:19:27.259[sip]   a=rtpmap:8 PCMA/8000
18:19:27.259[sip]   a=rtpmap:3 GSM/8000
18:19:27.259[sip]   a=rtpmap:111 G726-32/8000
18:19:27.259[sip]   a=rtpmap:101 telephone-event/8000
18:19:27.259[sip]   a=fmtp:101 0-16
18:19:27.259[sip]   a=ptime:20
18:19:27.259[sip]   a=maxptime:150
18:19:27.259[sip]   a=sendrecv
18:19:27.269[sip]   ------------------------------------------------------------------------
18:19:27.269[app:dbg]self_pre_invite_param() entering
18:19:27.269[app:dbg]stun_get_public_ip(port = 8000)
18:19:27.269[app:dbg]stun_get_public_ip: Always using local IP
18:19:27.269[app:dbg]sip: simple call (4) profile(2)
18:19:27.269[app:dbg]sip: get_support_params: profile 2 supported: 'timer, 100rel, replaces'
18:19:27.269[sip]send 334 bytes to udp/[192.168.100.90]:5060 at 01:50:03.050000:
18:19:27.269[sip]   ------------------------------------------------------------------------
18:19:27.269[sip]   SIP/2.0 100 Trying
18:19:27.269[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK173db2de
18:19:27.269[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=as60c1a347
18:19:27.269[sip]   To: <sip:1102@192.168.100.91:5060>
18:19:27.269[sip]   Call-ID: 4979b03056b6a00277558ec17742ce4f@192.168.100.90:5060
18:19:27.269[sip]   CSeq: 102 INVITE
18:19:27.269[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:19:27.269[sip]   Content-Length: 0
18:19:27.269[sip]
18:19:27.269[sip]   ------------------------------------------------------------------------
18:19:27.269[app:dbg]got nua_i_invite : 100(Trying)
18:19:27.269[app:dbg]NO CALL IN nua_i_invite == 100 : Trying
18:19:27.269[app:dbg]stun_get_public_ip(port = 8000)
18:19:27.269[app:dbg]stun_get_public_ip: Always using local IP
18:19:27.269[app:dbg]sip: get_support_params: profile 2 supported: 'timer, 100rel, replaces'
18:19:27.269[app:dbg]sip: INVITE from sip:1101@192.168.100.90
18:19:27.269[app:dbg]simple call
18:19:27.269[app:dbg]stun_get_public_ip(port = 8000)
18:19:27.269[app:dbg]stun_get_public_ip: Always using local IP
18:19:27.269[app:dbg]replaces 1, have accepted 0, ep 0x1b9288, state 1
18:19:27.269[app:dbg]available RTP ports: 23000...26000
18:19:27.269[app:dbg]selected port for current call: 23444
18:19:27.269[app:dbg]self_i_invite (8694): no alert_info received
18:19:27.269[app:dbg]sdp_codecs_init() init call sdp (empty)
18:19:27.269[app:dbg]sdp_codecs_set_ssup() ssup present 0 ssup yes
18:19:27.279[sip]recv 537 bytes from udp/[192.168.100.90]:5060 at 01:50:03.060000:
18:19:27.279[sip]   ------------------------------------------------------------------------
18:19:27.279[sip]   SIP/2.0 180 Ringing
18:19:27.279[sip]   Via: SIP/2.0/UDP 192.168.100.91;branch=z9hG4bKZyj15DBFDQece;received=192.168.100.91;rport=5060
18:19:27.279[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=jma478Q4j9mXp
18:19:27.279[sip]   To: <sip:1102@192.168.100.90>;tag=as0676e329
18:19:27.279[sip]   Call-ID: a28f2431-8002-1234-0a8d-a8f94b09c764
18:19:27.279[sip]   CSeq: 3302 INVITE
18:19:27.279[sip]   Server: FPBX-13.0.101(13.8.0)
18:19:27.279[sip]   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
18:19:27.279[sip]   Supported: replaces, timer
18:19:27.279[sip]   Session-Expires: 1800;refresher=uas
18:19:27.279[sip]   Contact: <sip:1102@192.168.100.90:5060>
18:19:27.279[sip]   Content-Length: 0
18:19:27.279[sip]
18:19:27.279[sip]   ------------------------------------------------------------------------
18:19:27.279[app:dbg]G711U: PT 0
18:19:27.279[app:dbg]sdp_codecs_add_g711u_item() pt 0
18:19:27.279[app:dbg]G711A: PT 8
18:19:27.279[app:dbg]sdp_codecs_add_g711a_item() pt 8
18:19:27.279[app:dbg]sdp_codecs_set_rfc2833() have no common rfc2833 events
18:19:27.279[app:dbg]sdp_codecs_set_rfc2833() present pt 101 remote fmtp 0-16, local fmtp
18:19:27.279[app:dbg]attr: name: ptime value: 20
18:19:27.279[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:19:27.279[app:dbg]attr: name: maxptime value: 150
18:19:27.279[app:dbg]sdp_codecs_dump() ssup absent on, ecan absent on, rfc present 101, nse absent 0, ptime present 20
18:19:27.279[app:dbg]sdp_codecs_dump() G723: none
18:19:27.279[app:dbg]sdp_codecs_dump() G711A:
18:19:27.279[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
18:19:27.279[app:dbg]sdp_codecs_dump() G711U:
18:19:27.279[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
18:19:27.279[app:dbg]stun_get_public_ip(port = 23444)
18:19:27.279[app:dbg]stun_get_public_ip: Always using local IP
18:19:27.279[app:dbg]self_i_invite: handle call id 0x02040019, call id 0x02040019
18:19:27.279[app:dbg]got nua_i_state : 100(Trying)
18:19:27.279[app:dbg]NO SIP IN nua_i_state == 100 : Trying
18:19:27.279[app:dbg]self_i_state(): call state 5: or : remote sdp : sdp_init no_oc
18:19:27.279[app:dbg]sip: call 02040019: SDP offer received
18:19:27.279[app:dbg]sdp_codecs_init() init call sdp (offer)
18:19:27.279[app:dbg]sdp_codecs_set_ssup() ssup present 0 ssup yes
18:19:27.279[app:dbg]sdp_codecs_set_rfc2833() have no common rfc2833 events
18:19:27.279[app:dbg]sdp_codecs_set_rfc2833() present pt 101 remote fmtp 0-16, local fmtp
18:19:27.279[app:dbg]attr: name: ptime value: 20
18:19:27.279[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:19:27.279[app:dbg]attr: name: maxptime value: 150
18:19:27.279[app:dbg]sip: call 02040019: media stream 0, creating proposed audio channel, remote RTP 192.168.100.90:18400
18:19:27.279[app:dbg]sip: call 02040019: select audio media
18:19:27.279[app:dbg]G711U: PT 0
18:19:27.279[app:dbg]G711A: PT 8
18:19:27.279[app:dbg]sip: call 02040019: remote SDP offer copy
18:19:27.279[app:dbg]sip: call 02040019: called from sip:1101@192.168.100.90 to sip:1102@192.168.100.91:5060
18:19:27.279[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
18:19:27.289[app:dbg]sip -[msg_call]-> pbx
18:19:27.289[app:dbg]ITC: [msg_call] -> pbx
18:19:27.289[app:dbg]SLIC 4: incoming call from 192.168.100.90:5060/1101("1101") payload 101 call ID: 02040019 group: -1
18:19:27.289[app:dbg]pbx: allocating memory for new call
18:19:27.289[app:dbg]pbx: created new incoming call for SLIC 4
18:19:27.289[app:dbg]self_call_create (4455): created
18:19:27.289[app:dbg]SLIC 4: -> ringing
18:19:27.289[app:info]SLIC 4: from state 'hangup' to state 'ringing'
18:19:27.289[app:dbg]CMD_CREATE_CONN: port = 4
18:19:27.289[app:dbg]Port 4: check vapi queue ('free') at vapi_create_chan:694
18:19:27.289[app:dbg]Chan 4: current state is INITIAL
18:19:27.289[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'create' at vapi_create_chan:720
18:19:27.289[app:dbg]VQ Conn 4 = MSP :        'create' =
18:19:27.289[app:dbg]Creating connection 4....
18:19:27.289[app:dbg]Chan 4: INITIAL -> CREATING
18:19:27.289[app:dbg]Created succefuly 4....
18:19:27.289[app:info]SLIC 4: has incoming call from 1101
18:19:27.289[app:dbg]port 4: port_seize
18:19:27.289[app:dbg]port 4: seize
18:19:27.289[app:dbg]port 4: seize has cadence pulse = 0, pause = 0
18:19:27.289[app:dbg]Set port 4 led to state 'LED_RINGING'
18:19:27.289[app:dbg]Port 4: user port 2, old state ringing, new state
18:19:27.289[app:dbg]Set port 4 led to state 'LED_OFF'
18:19:27.289[app:dbg]pbx -[msg_fxs_state]-> group
18:19:27.289[app:dbg]ITC: [msg_fxs_state] -> group
18:19:27.289[app:dbg]-----[GM] self_fxs_state()
18:19:27.289[app:dbg]Port 4: new state is ringing
18:19:27.289[app:dbg]self_callstate_received (6934): complete
18:19:27.289[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000004f
18:19:27.289[app:dbg]got nua_r_invite : 180(Ringing)
18:19:27.289[app:dbg]sip: call 00070025: INVITE: 180 Ringing
18:19:27.309[app:dbg]Contact/Record-route on answer to INVITE: sip:1102@192.168.100.90:5060
18:19:27.309[app:dbg]Setup new proxy addr for call; sip:1102@192.168.100.90:5060
18:19:27.309[app:dbg]call 00458789 got 180/Ringing - set received_1xx
18:19:27.309[app:dbg]sip: call 00070025: ringing back
18:19:27.309[app:WARN]No SDP description!!!
18:19:27.309[app:dbg]sip: call 00070025: 180 ringing without SDP descr
18:19:27.309[app:dbg]sip -[msg_free]-> pbx
18:19:27.309[app:dbg]got nua_i_state : 180(Ringing)
18:19:27.309[app:dbg]NO SIP IN nua_i_state == 180 : Ringing
18:19:27.309[app:dbg]self_i_state(): call state 3: : : sdp_sent have_oc
18:19:27.309[app:dbg]got nua_r_set_params : 200(OK)
18:19:27.309[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
18:19:27.309[app:dbg]got nua_r_set_params : 200(OK)
18:19:27.309[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
18:19:27.309[app:dbg]got nua_r_set_params : 200(OK)
18:19:27.309[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
18:19:27.319[app:dbg]pbx -[msg_free]-> sip
18:19:27.319[app:dbg]ITC: [msg_free] -> sip
18:19:27.319[app:dbg]sip: call 02040019: endpoint 4 ringing
18:19:27.319[app:dbg]sip: call 02040019,sip: INVITE: 180 Ringing
18:19:27.319[app:dbg]send_18x() call 0x02040019, hdr <none>, sip, rel mode/cfg off/supp/req, inv w/ sdp, to port
18:19:27.319[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:19:27.319[app:dbg]sdp_codecs_dump() ssup absent on, ecan absent on, rfc present 101, nse absent 0, ptime present 20
18:19:27.319[app:dbg]sdp_codecs_dump() G723: none
18:19:27.319[app:dbg]sdp_codecs_dump() G711A:
18:19:27.319[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
18:19:27.319[app:dbg]sdp_codecs_dump() G711U:
18:19:27.319[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
18:19:27.319[app:dbg]sdp_codecs_g711a_add_to_media_attrs() g711a: have one at last
18:19:27.319[app:dbg]sdp_codecs_g711u_add_to_media_attrs() g711u: have one at last
18:19:27.319[app:dbg]sdp_codecs_rfc2833_add_to_media_attrs() present, pt 101
18:19:27.319[app:dbg]sdp_codecs_nse_add_to_media_attrs() absent, pt 0
18:19:27.319[app:dbg]sdp_codecs_ptime_add_to_attrs() ptime present 20
18:19:27.319[app:dbg]sdp_codecs_ecan_add_to_attrs() ecan absent on
18:19:27.319[app:dbg]sdp_codecs_ssup_add_to_attrs() ssup absent on
18:19:27.319[app:dbg]sdp_tail:  8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
18:19:27.319[app:dbg]make_sdp: SDP: s=Session SDP
m=audio 23444 RTP/AVP 8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
18:19:27.319[app:dbg]send_18x(): respond w/o sdp 0, sdp 1
18:19:27.319[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
18:19:27.319[app:dbg]Early media is enabled
18:19:27.319[app:dbg]Sending 183 Session progress with SDP
18:19:27.319[sip]send 778 bytes to udp/[192.168.100.90]:5060 at 01:50:03.100000:
18:19:27.319[sip]   ------------------------------------------------------------------------
18:19:27.319[sip]   SIP/2.0 183 Session Progress
18:19:27.319[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK173db2de
18:19:27.319[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=as60c1a347
18:19:27.319[sip]   To: <sip:1102@192.168.100.91:5060>;tag=KX3v9387FjBgj
18:19:27.319[sip]   Call-ID: 4979b03056b6a00277558ec17742ce4f@192.168.100.90:5060
18:19:27.319[sip]   CSeq: 102 INVITE
18:19:27.319[sip]   Contact: <sip:1102@192.168.100.91:5060>
18:19:27.319[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:19:27.319[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:19:27.319[sip]   Supported: timer, 100rel, replaces
18:19:27.319[sip]   Content-Type: application/sdp
18:19:27.319[sip]   Content-Disposition: session
18:19:27.319[sip]   Content-Length: 178
18:19:27.319[sip]
18:19:27.319[sip]   v=0
18:19:27.319[sip]   o=- 9065440976955983981 6949752170194992596 IN IP4 192.168.100.91
18:19:27.319[sip]   s=Session SDP
18:19:27.319[sip]   c=IN IP4 192.168.100.91
18:19:27.319[sip]   t=0 0
18:19:27.319[sip]   m=audio 23444 RTP/AVP 8
18:19:27.319[sip]   a=rtpmap:8 PCMA/8000
18:19:27.319[sip]   a=ptime:20
18:19:27.319[sip]   ------------------------------------------------------------------------
18:19:27.329[app:dbg]SLIC 4: list of all calls:
18:19:27.329[app:dbg]   call ID: 02040019
18:19:27.329[app:dbg]got nua_i_state : 183(Session Progress)
18:19:27.329[app:dbg]NO SIP IN nua_i_state == 183 : Session Progress
18:19:27.329[app:dbg]self_i_state(): call state 6: as : local sdp : sdp_recv no_oc
18:19:27.329[app:dbg]sip: call 02040019: SDP answer sent for the first invite
18:19:27.329[app:dbg]self_destroy_current_media() nothing to destroy
18:19:27.329[app:dbg]self_start_media: 1. handle call id 0x02040019, call id 0x02040019
18:19:27.329[app:dbg]sip: set options: call 02040019: media stream 0: 192.168.100.91:23444 -> 192.168.100.90:18400: MFPT 0 <drop>
18:19:27.329[app:dbg]self_itc_codec(): payload 8
18:19:27.329[app:dbg]self_itc_codec(): payload 8
18:19:27.329[app:dbg]Supported codec[0]: <G.711A>:8, vbd off, vad on, ecan on
18:19:27.329[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
18:19:27.329[app:dbg]validate_ptime() codec G.711A, ptime 20, check_bigger 1, present 1
18:19:27.329[app:dbg]validate_ptime() using 20
18:19:27.329[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:19:27.329[app:dbg]self_start_media: 2. handle call id 0x02040019, call id 0x02040019
18:19:27.329[app:dbg]sip -[msg_set_media]-> pbx
18:19:27.329[app:dbg]sip: call 02040019: local SDP offer copy
18:19:27.339[app:dbg]incom_calls_add() add call 0x02040019, group -1, task <sip> to list
18:19:27.339[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.339[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000004f result 0x00000000
18:19:27.339[app:dbg]slic4. Event 6.
18:19:27.339[app:dbg]slic 4. Ring on event
18:19:27.339[app:dbg]Set port 4 led to state 'LED_RINGING'
18:19:27.339[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000000
18:19:27.349[app:dbg]port_process (11051): seize next tone
18:19:27.349[app:dbg]port 4: clear
18:19:27.349[app:dbg]Set port 4 led to state 'LED_OFF'
18:19:27.349[app:dbg]port 4: port_seize
18:19:27.349[app:dbg]port 4: seize
18:19:27.349[app:dbg]port 4: seize has cadence pulse = 1000, pause = 4000
18:19:27.349[app:dbg]Set port 4 led to state 'LED_RINGING'
18:19:27.349[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.349[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000000 result 0x00000000
18:19:27.349[app:dbg]vapi: Conn 4 - << CREATED >>
18:19:27.349[app:dbg]vapi: Conn 4 - fix DTMF detector
18:19:27.349[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000049
18:19:27.359[app:dbg]ITC: [msg_free] -> pbx
18:19:27.359[app:dbg]SLIC 7: peer ringing
18:19:27.359[app:dbg]SLIC 7: -> ringback (1)
18:19:27.359[app:info]SLIC 7: from state 'calling' to state 'ringback'
18:19:27.369[app:dbg]port_start_tone(7 23 0 0)
18:19:27.369[app:dbg]CMD_START_TONE: port = 7
18:19:27.369[app:dbg]Port 7: check vapi queue ('free') at vapi_start_tone_chan:1384
18:19:27.369[app:dbg]Chan 7: current state is CREATED
18:19:27.369[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'start_tone' at vapi_start_tone_chan:1421
18:19:27.369[app:dbg]VQ Conn 7 = MSP :    'start_tone' =
18:19:27.379[app:dbg]chan 7 start tone, id=23, direction=TDM
18:19:27.379[app:dbg]Port 7: user port 1, old state ringback, new state
18:19:27.379[app:dbg]Set port 7 led to state 'LED_ON'
18:19:27.379[app:dbg]pbx -[msg_fxs_state]-> group
18:19:27.379[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000922
18:19:27.379[app:dbg]ITC: [msg_fxs_state] -> group
18:19:27.379[app:dbg]-----[GM] self_fxs_state()
18:19:27.379[app:dbg]Port 7: new state is ringback
18:19:27.399[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.399[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000049 result 0x00000000
18:19:27.399[app:dbg]vapi: Conn 4 - fix CNG generator
18:19:27.399[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000004c
18:19:27.409[app:dbg]ITC: [msg_set_media] -> pbx
18:19:27.409[app:dbg]self_on_set_media: call id 0x02040019 tx/rx 1/1
18:19:27.409[app:dbg]dump_port_calls() SLIC 4:
18:19:27.409[app:dbg]Q:(0x329800,0x02040019,(nil))
18:19:27.409[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:19:27.409[app:dbg]SLIC 4: TX start / RX start: 192.168.100.91:23444->192.168.100.90:18400, <G.711A:8>
18:19:27.409[app:dbg]SLIC 4: send only 0 vad 1 g723_hr 1 vbd 0, ecan 1 rfc2833 pt 101, NSE pt 0, MFPT 0
18:19:27.409[app:dbg]incom_calls_set_media_started() call 0x02040019, group -1, task <sip> media started
18:19:27.409[app:dbg]self_set_media_start(): set ptime to 20
18:19:27.409[app:dbg]port_set_ip_param
18:19:27.409[app:dbg]set media param for '4', 192.168.100.91:23444, mode=local, random 83
18:19:27.409[app:dbg]port_set_ip_param
18:19:27.409[app:dbg]set media param for '4', 192.168.100.90:18400, mode=remote, random 83
18:19:27.409[app:dbg]CMD_CREATE_CONN: port = 4
18:19:27.409[app:dbg]Port 4: check vapi queue ('busy''create') at vapi_create_chan:694
18:19:27.409[app:dbg]Port 4 put cmd 'create',cur 'create' to queue at (vapi_create_chan:700)
18:19:27.409[app:dbg]VQ Conn 4 = MSP :        'create' =
18:19:27.409[app:dbg]VQ Conn 4 + 02  :        'create'  + <-get_ptr
18:19:27.409[app:dbg]SLIC 4: starting media (G.711A) 192.168.100.91:23444 -> 192.168.100.90:18400
18:19:27.409[app:dbg]port 4: start voice - first time
18:19:27.409[app:dbg]port_start_voice() chan 04: remote IP <192.168.100.90> (arp query 0 times)
18:19:27.409[app:dbg]chan 4: get mac succesfull, repeat 0 times
18:19:27.409[app:dbg]CMD_START_VOICE: port = 4
18:19:27.409[app:dbg]vapi_set_chan_param: chan=4 hold=0 deactivate=0
18:19:27.409[app:dbg]Port 4: check vapi queue ('busy''create') at vapi_set_chan_param:2136
18:19:27.409[app:dbg]Port 4 put cmd 'start voice',cur 'create' to queue at (vapi_set_chan_param:2148)
18:19:27.409[app:dbg]VQ Conn 4 = MSP :        'create' =
18:19:27.409[app:dbg]VQ Conn 4 + 02  :        'create'  + <-get_ptr
18:19:27.409[app:dbg]VQ Conn 4 + 03  :   'start voice'  +
18:19:27.409[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.409[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000922 result 0x00000000
18:19:27.409[app:dbg]Conn 7: Start tone - Successfull
18:19:27.409[app:dbg]Port 7: check vapi queue ('busy''start_tone') at vapi_next_ops:2532
18:19:27.419[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.419[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000004c result 0x00000000
18:19:27.419[app:dbg]vapi: Conn 4 - caller id Set param
18:19:27.419[app:dbg]vapi: chan '4' set param Caller ID
18:19:27.419[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000000c
18:19:27.429[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.429[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000000c result 0x00000000
18:19:27.429[app:dbg]vapi: Conn 4 - enable ind ptime and pt
18:19:27.429[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000004a
18:19:27.439[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.439[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000004a result 0x00000000
18:19:27.439[app:dbg]Chan 4: CREATING -> CREATED
18:19:27.439[app:dbg]Port 4: check vapi queue ('busy''create') at vapi_next_ops:2532
18:19:27.439[app:dbg]Port 4 get cmd 'create' from queue at (vapi_next_ops:2551)
18:19:27.439[app:dbg]VQ Conn 4 + 03  :   'start voice'  + <-get_ptr
18:19:27.439[app:dbg]Port 4: check vapi queue ('free') at vapi_create_chan:694
18:19:27.439[app:dbg]Chan 4: current state is CREATED
18:19:27.439[app:dbg]chan 4: no need to create - already exists
18:19:27.439[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2694
18:19:27.439[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2532
18:19:27.439[app:dbg]Port 4 get cmd 'start voice' from queue at (vapi_next_ops:2551)
18:19:27.439[app:dbg]vapi_set_chan_param: chan=4 hold=0 deactivate=0
18:19:27.439[app:dbg]Port 4: check vapi queue ('free') at vapi_set_chan_param:2136
18:19:27.439[app:dbg]Chan 4: current state is CREATED
18:19:27.439[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'start voice' at vapi_set_chan_param:2160
18:19:27.439[app:dbg]VQ Conn 4 = MSP :   'start voice' =
18:19:27.439[app:dbg]Conn 4 Eth src=a8:f9:4b:09:c7:64, dst=00:00:00:00:00:00
18:19:27.439[app:dbg]Conn 4 IP src=192.168.100.91:23444, dst=192.168.100.90:18400
18:19:27.439[app:dbg]CHECK REQID: 0x00000502(Conn 4)
18:19:27.439[app:dbg]vapi: Conn 4. Disable - Ok
18:19:27.439[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000502
18:19:27.449[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.449[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000502 result 0x00000000
18:19:27.449[app:dbg]VOIP_DISABLE: chan = 4
18:19:27.449[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:19:27.449[app:dbg]vapi: create: TDM channel 4 Set SSRC to 27CC59E
18:19:27.449[app:dbg]vapi: Conn 4. Set src/dst eth mac - Ok
18:19:27.449[app:dbg]Reserved IP: 192.168.253.1
18:19:27.449[app:dbg]vapi_cb_setchan: ch4. msp_ip = 192.168.253.2
18:19:27.449[app:dbg]IP PARAMS: 1FDA8C0 30444 2FDA8C0 30444
18:19:27.449[app:dbg]vapi: Conn 4. Set src/dst ip addr - ok
18:19:27.449[app:dbg]Create RX-TX media for SLIC 4(sendonly: 0, rtcp: 0)
18:19:27.449[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000508
18:19:27.459[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.459[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000508 result 0x00000000
18:19:27.459[app:dbg]VOIP_SET_IP: chan = 4
18:19:27.459[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:19:27.459[app:dbg]chan 4. vapi_cb_setchan: configure ecan on
18:19:27.459[app:dbg]vapi_passthru_echocan_cb() NLP, DCRF enabled, session 0, on 1, value 0x8007
18:19:27.459[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000547
18:19:27.469[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.469[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000547 result 0x00000000
18:19:27.469[app:dbg]VOIP_SSRC_FILT: chan = 4
18:19:27.469[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:19:27.469[app:dbg]chan 4. vapi_cb_setchan: VOIP_SSRC_FILT
18:19:27.469[app:dbg]vapi_cb_setchan: ch4. msp_ip = 192.168.253.2
18:19:27.469[app:dbg]RTCP IP PARAMS: 1FDA8C0 30445 2FDA8C0 30445
18:19:27.469[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000052b
18:19:27.479[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.479[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000052b result 0x00000000
18:19:27.479[app:dbg]VOIP_SET_IP2: chan = 4
18:19:27.479[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:19:27.479[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PT
18:19:27.479[app:dbg]for chan <4> set codec type = 5 'G711A'
18:19:27.479[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000054e
18:19:27.489[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.489[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000054e result 0x00000000
18:19:27.489[app:dbg]UNKNOWN_CMD: chan = 4
18:19:27.489[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:19:27.489[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_CODEC
18:19:27.489[app:dbg]set_packet_interval = 20
18:19:27.489[app:dbg]vapi: Conn 4. Set 'Packet interval' 20
18:19:27.489[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PACKET
18:19:27.489[app:dbg]SET TX PT: 101
18:19:27.489[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000510
18:19:27.499[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.499[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000510 result 0x00000000
18:19:27.499[app:dbg]VOIP_SET_PACKET2: chan = 4
18:19:27.499[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:19:27.499[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PACKET2
18:19:27.499[app:dbg]SET RX PT: 101
18:19:27.499[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000513
18:19:27.509[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.509[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000513 result 0x00000000
18:19:27.509[app:dbg]VOIP_SET_DTMFOPT: chan = 4
18:19:27.509[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:19:27.509[app:dbg]vapi: Chan 4 set chach (packet mode)
18:19:27.509[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_DTMFOPT dtmf 0, pt 101
18:19:27.509[app:dbg]Enable voice DTMF tones
18:19:27.509[app:dbg]Set RFC2833 PT: 101(01A5, 65FF)
18:19:27.509[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_DTMFOPT2
18:19:27.509[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PT2
18:19:27.509[app:dbg]vapi: Conn 4. Enable RTP indication
18:19:27.509[app:dbg]chan 4. vapi_cb_setchan: VOIP_ENABLE_RTP_IND
18:19:27.509[app:dbg]chan 4: set jitter buffer options
18:19:27.509[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_INDCTL
18:19:27.509[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_JBOPT
18:19:27.509[app:dbg]vapi: Conn 4. Set tone ctl options
18:19:27.509[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_VLAN
18:19:27.509[app:dbg]VAD: 1 CNG: 0 PTE: 20
18:19:27.509[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000516
18:19:27.519[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.519[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000516 result 0x00000000
18:19:27.519[app:dbg]VOIP_SET_VCEOPT: chan = 4
18:19:27.519[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:19:27.519[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_VCEOPT
18:19:27.519[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000518
18:19:27.529[app:dbg]vapi_proc_event: VAPI_CB
18:19:27.529[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000518 result 0x00000000
18:19:27.529[app:dbg]VOIP_SET_VOICE: chan = 4
18:19:27.529[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:19:27.529[app:dbg]vapi_cb_setchan() Conn 4: set eActive state ok
18:19:27.529[app:dbg]vapi_cb_setchan() Conn 4: creating connection at state ps_ringing - early media mode
18:19:27.529[app:dbg]port 4: mute media for generating caller id
18:19:27.529[app:dbg]Port 4: check vapi queue ('busy''start voice') at vapi_next_ops:2532
18:19:27.529[app:dbg]Mute all RX-TX medias on SLIC 4
18:19:27.529[app:dbg]Mute media on chan 4[mute 1]
18:19:28.379[app:dbg]slic4. Event 7.
18:19:28.379[app:dbg]slic 4. Ring off event
18:19:28.379[app:dbg]Set port 4 led to state 'LED_OFF'
18:19:28.379[app:dbg]Set port 4 led to state 'LED_OFF'
18:19:28.899[app:info]SLIC 4: FSK caller-id generated
18:19:28.899[app:dbg]CMD_START_CID: port = 4
18:19:28.899[app:dbg]Port 4: check vapi queue ('free') at vapi_generate_offhook_caller_id:2885
18:19:28.899[app:dbg]Chan 4: current state is CREATED
18:19:28.899[app:info]Channel 4. Caller-ID type I. Phone: <1101>, name:<"1101">
18:19:28.899[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'gen_offhook_caller_id' at vapi_generate_offhook_caller_id:2906
18:19:28.899[app:dbg]VQ Conn 4 = MSP : 'gen_offhook_caller_id' =
18:19:28.899[app:dbg]Caller ID date: 116.4.18 18:19:28
18:19:28.899[app:dbg]vapi: chan '4' generate Caller ID len=26
18:19:28.899[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000a35
18:19:28.899[app:dbg]vapi_proc_event: VAPI_CB
18:19:28.899[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000a35 result 0x00000000
18:19:28.899[app:dbg]chan 4: Offhook Caller ID generated
18:19:28.899[app:dbg]Port 4: check vapi queue ('busy''gen_offhook_caller_id') at vapi_next_ops:2532
18:19:28.929[app:dbg]slic4. Event 2.
18:19:28.929[app:dbg]slic 4. Off-hook event
18:19:28.929[app:dbg]Set port 4 led to state 'LED_ON'
18:19:28.929[app:dbg]HIO: offhook TDM port '4' port enabled 1
18:19:28.929[app:dbg]SLIC 4 (1102): offhook state: ringing
18:19:28.929[app:dbg]regex ID 4: dial reset
18:19:28.929[app:dbg]SLIC 4: -> talking(call id: 02040019)
18:19:28.929[app:dbg]pbx -[msg_answer]-> sip
18:19:28.929[app:info]SLIC 4: from state 'ringing' to state 'talking'
18:19:28.929[app:dbg]CMD_STOP_TONE: port = 4
18:19:28.929[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:19:28.929[app:dbg]Chan 4: current state is CREATED
18:19:28.929[app:ERR]chan 4: no generated tones!
18:19:28.929[app:dbg]vapi_chan.c:1510: conn 4 peek cmd 'no event' from queue
18:19:28.929[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:320
18:19:28.929[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2532
18:19:28.929[app:dbg]ITC: [msg_answer] -> sip
18:19:28.929[app:dbg]sip: call 02040019: endpoint 4 answered
18:19:28.929[app:dbg]sip: call 02040019: INVITE: 200 OK SIP_T NO
18:19:28.929[app:dbg]sip: call 02040019: set endpoint 4
18:19:28.929[app:dbg]self_on_answer() sdp state <init> - create offer sdp, ptime present/20
18:19:28.929[app:dbg]sdp_codecs_init() init call sdp (offer)
18:19:28.929[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:19:28.929[app:dbg]sdp_codecs_dump() ssup present on, ecan absent on, rfc absent 101, nse absent 0, ptime present 20
18:19:28.929[app:dbg]sdp_codecs_dump() G723: none
18:19:28.929[app:dbg]sdp_codecs_dump() G711A:
18:19:28.929[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
18:19:28.929[app:dbg]sdp_codecs_dump() G711U:
18:19:28.929[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
18:19:28.929[app:dbg]sdp_codecs_g711a_add_to_media_attrs() g711a: have one at last
18:19:28.929[app:dbg]sdp_codecs_g711u_add_to_media_attrs() g711u: have one at last
18:19:28.929[app:dbg]sdp_codecs_rfc2833_add_to_media_attrs() absent, pt 101
18:19:28.929[app:dbg]sdp_codecs_nse_add_to_media_attrs() absent, pt 0
18:19:28.929[app:dbg]sdp_codecs_ptime_add_to_attrs() ptime present 20
18:19:28.929[app:dbg]sdp_codecs_ecan_add_to_attrs() ecan absent on
18:19:28.929[app:dbg]sdp_codecs_ssup_add_to_attrs() ssup present on
18:19:28.929[app:dbg]sdp_tail:  8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
a=silenceSupp:on - - - -
18:19:28.929[app:dbg]make_sdp: SDP: s=Session SDP
m=audio 23444 RTP/AVP 8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
a=silenceSupp:on - - - -
18:19:28.929[app:dbg]sdp_codecs_get_rfc2833: present=0 pt=101
18:19:28.929[app:WARN][get_group_profile_id]-1 is not group index!!!!
18:19:28.929[app:dbg]self_on_answer: call_id = 02040019 need_exchange_at_answer = 0
18:19:28.929[app:dbg]Unmute all RX-TX medias on SLIC 4
18:19:28.929[app:dbg]Unmute media on chan 4[mute 0]
18:19:28.929[sip]send 830 bytes to udp/[192.168.100.90]:5060 at 01:50:04.710000:
18:19:28.929[sip]   ------------------------------------------------------------------------
18:19:28.929[sip]   SIP/2.0 200 OK
18:19:28.929[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK173db2de
18:19:28.929[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=as60c1a347
18:19:28.929[sip]   To: <sip:1102@192.168.100.91:5060>;tag=KX3v9387FjBgj
18:19:28.949[sip]   Call-ID: 4979b03056b6a00277558ec17742ce4f@192.168.100.90:5060
18:19:28.949[sip]   CSeq: 102 INVITE
18:19:28.949[sip]   Contact: <sip:1102@192.168.100.91:5060>
18:19:28.949[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:19:28.949[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:19:28.949[sip]   Require: timer
18:19:28.949[sip]   Supported: timer, 100rel, replaces
18:19:28.949[sip]   Session-Expires: 1800;refresher=uac
18:19:28.949[sip]   Min-SE: 120
18:19:28.949[sip]   Content-Type: application/sdp
18:19:28.949[sip]   Content-Disposition: session
18:19:28.949[sip]   Content-Length: 178
18:19:28.949[sip]
18:19:28.949[sip]   v=0
18:19:28.949[sip]   o=- 9065440976955983981 6949752170194992596 IN IP4 192.168.100.91
18:19:28.949[sip]   s=Session SDP
18:19:28.949[sip]   c=IN IP4 192.168.100.91
18:19:28.949[sip]   t=0 0
18:19:28.949[sip]   m=audio 23444 RTP/AVP 8
18:19:28.949[sip]   a=rtpmap:8 PCMA/8000
18:19:28.949[sip]   a=ptime:20
18:19:28.949[sip]   ------------------------------------------------------------------------
18:19:28.949[app:dbg]got nua_i_state : 200(OK)
18:19:28.949[app:dbg]NO SIP IN nua_i_state == 200 : OK
18:19:28.949[app:dbg]self_i_state(): call state 7: as : local sdp : sdp_init have_oc
18:19:28.949[sip]recv 405 bytes from udp/[192.168.100.90]:5060 at 01:50:04.730000:
18:19:28.949[sip]   ------------------------------------------------------------------------
18:19:28.949[sip]   ACK sip:1102@192.168.100.91:5060 SIP/2.0
18:19:28.949[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK4d597370
18:19:28.949[sip]   Max-Forwards: 70
18:19:28.949[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=as60c1a347
18:19:28.949[sip]   To: <sip:1102@192.168.100.91:5060>;tag=KX3v9387FjBgj
18:19:28.949[sip]   Contact: <sip:1101@192.168.100.90:5060>
18:19:28.949[sip]   Call-ID: 4979b03056b6a00277558ec17742ce4f@192.168.100.90:5060
18:19:28.949[sip]   CSeq: 102 ACK
18:19:28.949[sip]   User-Agent: FPBX-13.0.101(13.8.0)
18:19:28.949[sip]   Content-Length: 0
18:19:28.949[sip]
18:19:28.949[sip]   ------------------------------------------------------------------------
18:19:28.949[app:dbg]got nua_i_ack : 200(OK)
18:19:28.949[app:dbg]got nua_i_state : 200(OK)
18:19:28.949[app:dbg]NO SIP IN nua_i_state == 200 : OK
18:19:28.949[app:dbg]self_i_state(): call state 8: : : sdp_init have_oc
18:19:28.949[app:dbg]sip: call 02040019: ACK from sip:1101@192.168.100.90
18:19:28.949[app:dbg]sip: call 02040019: ACK from sip:1101@192.168.100.90
18:19:28.949[app:dbg]got nua_i_active : 200(Call active)
18:19:28.949[app:dbg]NO SIP IN nua_i_active == 200 : Call active
18:19:28.959[app:dbg]Port 4: user port 2, old state talking, new state
18:19:28.959[app:dbg]Set port 4 led to state 'LED_ON'
18:19:28.959[app:dbg]pbx -[msg_fxs_state]-> group
18:19:28.969[app:dbg]ITC: [msg_fxs_state] -> group
18:19:28.969[app:dbg]-----[GM] self_fxs_state()
18:19:28.969[app:dbg]Port 4: new state is talking
18:19:28.979[sip]recv 804 bytes from udp/[192.168.100.90]:5060 at 01:50:04.730000:
18:19:28.979[sip]   ------------------------------------------------------------------------
18:19:28.979[sip]   SIP/2.0 200 OK
18:19:28.979[sip]   Via: SIP/2.0/UDP 192.168.100.91;branch=z9hG4bKZyj15DBFDQece;received=192.168.100.91;rport=5060
18:19:28.979[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=jma478Q4j9mXp
18:19:28.979[sip]   To: <sip:1102@192.168.100.90>;tag=as0676e329
18:19:28.979[sip]   Call-ID: a28f2431-8002-1234-0a8d-a8f94b09c764
18:19:28.979[sip]   CSeq: 3302 INVITE
18:19:28.979[sip]   Server: FPBX-13.0.101(13.8.0)
18:19:28.979[sip]   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
18:19:28.979[sip]   Supported: replaces, timer
18:19:28.979[sip]   Session-Expires: 1800;refresher=uas
18:19:28.979[sip]   Contact: <sip:1102@192.168.100.90:5060>
18:19:28.979[sip]   Content-Type: application/sdp
18:19:28.979[sip]   Require: timer
18:19:28.979[sip]   Content-Length: 223
18:19:28.979[sip]
18:19:28.979[sip]   v=0
18:19:28.979[sip]   o=root 2052809765 2052809765 IN IP4 192.168.100.90
18:19:28.979[sip]   s=Asterisk PBX 13.8.0
18:19:28.979[sip]   c=IN IP4 192.168.100.90
18:19:28.979[sip]   t=0 0
18:19:28.979[sip]   m=audio 19160 RTP/AVP 0 8
18:19:28.979[sip]   a=rtpmap:0 PCMU/8000
18:19:28.979[sip]   a=rtpmap:8 PCMA/8000
18:19:28.979[sip]   a=ptime:20
18:19:28.979[sip]   a=maxptime:150
18:19:28.979[sip]   a=sendrecv
18:19:28.979[sip]   ------------------------------------------------------------------------
18:19:28.979[app:dbg]got nua_r_invite : 200(OK)
18:19:28.979[app:dbg]sip: call 00070025: INVITE: 200 OK
18:19:28.979[app:dbg]attr: name: ptime value: 20
18:19:28.979[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:19:28.979[app:dbg]attr: name: maxptime value: 150
18:19:28.979[app:dbg]sip: call 00070025: current status (200)
18:19:28.979[app:dbg]got nua_i_state : 200(OK)
18:19:28.979[app:dbg]NO SIP IN nua_i_state == 200 : OK
18:19:28.979[app:dbg]self_i_state(): call state 4: ar : remote sdp : sdp_sent have_oc
18:19:28.979[app:dbg]sip: call 00070025: SDP answer received
18:19:28.979[app:dbg]sip: call 00070025: calltype 1, mode_codec 0, codec 0
18:19:28.979[app:dbg]sip: call 00070025: SDP answer received
18:19:28.979[app:dbg]self_destroy_current_media() nothing to destroy
18:19:28.989[app:dbg]sdp_codecs_get_rfc2833: present=0 pt=101
18:19:28.989[app:WARN]update_call_rfc2833_sdp() no rfc2833 on local side - do not update from remote
18:19:28.989[app:dbg]self_start_media: 1. handle call id 0x00070025, call id 0x00070025
18:19:28.989[app:dbg]sip: set options: call 00070025: media stream 0: 192.168.100.91:23440 -> 192.168.100.90:19160: MFPT 0 <drop>
18:19:28.989[app:dbg]self_itc_codec(): payload 0
18:19:28.989[app:dbg]sip_set_rxtx_opts(): check rtpm <PCMU>:0
18:19:28.989[app:dbg]sip_set_rxtx_opts(): check offered 0: 8
18:19:28.989[app:dbg]sip_set_rxtx_opts(): check offered 1: 0
18:19:28.989[app:dbg]self_itc_codec(): payload 0
18:19:28.989[app:dbg]Supported codec[0]: <G.711U>:0, vbd off, vad on, ecan on
18:19:28.989[app:dbg]validate_ptime() codec G.711U, ptime 20, check_bigger 1, present 1
18:19:28.989[app:dbg]validate_ptime() using 20
18:19:28.989[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:19:28.989[app:dbg]sip_set_rxtx_opts(): check rtpm <PCMA>:8
18:19:28.989[app:dbg]sip_set_rxtx_opts(): check offered 0: 8
18:19:28.999[app:dbg]self_itc_codec(): payload 8
18:19:28.999[app:dbg]Supported codec[1]: <G.711A>:8, vbd off, vad on, ecan on
18:19:28.999[app:dbg]validate_ptime() codec G.711U, ptime 20, check_bigger 1, present 1
18:19:28.999[app:dbg]validate_ptime() using 20
18:19:28.999[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:19:28.999[app:dbg]sdp_codecs_get_rfc2833: present=0 pt=101
18:19:28.999[app:dbg]validate_ptime() codec G.711U, ptime 20, check_bigger 1, present 1
18:19:28.999[app:dbg]validate_ptime() using 20
18:19:28.999[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:19:28.999[app:dbg]self_start_media: 2. handle call id 0x00070025, call id 0x00070025
18:19:28.999[app:dbg]sip -[msg_set_media]-> pbx
18:19:28.999[app:dbg]sip: call 00070025: call answered
18:19:28.999[app:dbg]sip -[msg_answer]-> pbx
18:19:28.999[app:dbg]sip: call 00070025: ACK to sip:1102@192.168.100.90
18:19:28.999[sip]send 522 bytes to udp/[192.168.100.90]:5060 at 01:50:04.780000:
18:19:28.999[sip]   ------------------------------------------------------------------------
18:19:28.999[sip]   ACK sip:1102@192.168.100.90:5060 SIP/2.0
18:19:28.999[sip]   Via: SIP/2.0/UDP 192.168.100.91;rport;branch=z9hG4bK07Bt78Uja04yS
18:19:28.999[sip]   Max-Forwards: 70
18:19:28.999[sip]   From: "1101" <sip:1101@192.168.100.90>;tag=jma478Q4j9mXp
18:19:28.999[sip]   To: <sip:1102@192.168.100.90>;tag=as0676e329
18:19:28.999[sip]   Call-ID: a28f2431-8002-1234-0a8d-a8f94b09c764
18:19:28.999[sip]   CSeq: 3302 ACK
18:19:28.999[sip]   Contact: <sip:1101@192.168.100.91:5060>
18:19:28.999[sip]   Authorization: Digest username="1101", realm="asterisk", nonce="1c5be4af", algorithm=MD5, uri="sip:1102@192.168.100.90", response="fb2b9b7dc6638e8e2ed43799fd4136c5"
18:19:28.999[sip]   Content-Length: 0
18:19:28.999[sip]
18:19:28.999[sip]   ------------------------------------------------------------------------
18:19:28.999[app:dbg]got nua_r_set_params : 200(OK)
18:19:28.999[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
18:19:28.999[app:dbg]got nua_i_state : 200(ACK sent)
18:19:28.999[app:dbg]NO SIP IN nua_i_state == 200 : ACK sent
18:19:28.999[app:dbg]self_i_state(): call state 8: : : sdp_init have_oc
18:19:28.999[app:dbg]sip: call 00070025: ACK from sip:1101@192.168.100.90
18:19:28.999[app:dbg]got nua_i_active : 200(Call active)
18:19:28.999[app:dbg]NO SIP IN nua_i_active == 200 : Call active
18:19:28.999[app:dbg]dump_port_calls() SLIC 4:
18:19:29.009[app:dbg]Q:(0x329800,0x02040019,(nil))
18:19:29.009[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:19:29.019[app:dbg]ITC: [msg_set_media] -> pbx
18:19:29.019[app:dbg]self_on_set_media: call id 0x00070025 tx/rx 1/1
18:19:29.019[app:dbg]dump_port_calls() SLIC 7:
18:19:29.019[app:dbg]Q:(0x32c800,0x00070025,(nil))
18:19:29.019[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:19:29.019[app:dbg]SLIC 7: TX start / RX start: 192.168.100.91:23440->192.168.100.90:19160, <G.711U:0>
18:19:29.019[app:dbg]SLIC 7: send only 0 vad 1 g723_hr 1 vbd 0, ecan 1 rfc2833 pt -1, NSE pt 0, MFPT 0
18:19:29.019[app:dbg]self_set_media_start(): set ptime to 20
18:19:29.019[app:dbg]port_set_ip_param
18:19:29.019[app:dbg]set media param for '7', 192.168.100.91:23440, mode=local, random 57
18:19:29.019[app:dbg]port_set_ip_param
18:19:29.019[app:dbg]set media param for '7', 192.168.100.90:19160, mode=remote, random 57
18:19:29.019[app:dbg]CMD_CREATE_CONN: port = 7
18:19:29.019[app:dbg]Port 7: check vapi queue ('free') at vapi_create_chan:694
18:19:29.019[app:dbg]Chan 7: current state is CREATED
18:19:29.019[app:dbg]chan 7: no need to create - already exists
18:19:29.019[app:dbg]Port 7: check vapi queue ('free') at __cmd_engine:320
18:19:29.019[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2532
18:19:29.019[app:dbg]SLIC 7: starting media (G.711U) 192.168.100.91:23440 -> 192.168.100.90:19160
18:19:29.019[app:dbg]port 7: start voice - first time
18:19:29.019[app:dbg]port_start_voice() chan 07: remote IP <192.168.100.90> (arp query 0 times)
18:19:29.019[app:dbg]chan 7: get mac succesfull, repeat 0 times
18:19:29.019[app:dbg]CMD_START_VOICE: port = 7
18:19:29.019[app:dbg]vapi_set_chan_param: chan=7 hold=0 deactivate=0
18:19:29.019[app:dbg]Port 7: check vapi queue ('free') at vapi_set_chan_param:2136
18:19:29.019[app:dbg]Chan 7: current state is CREATED
18:19:29.019[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'start voice' at vapi_set_chan_param:2160
18:19:29.019[app:dbg]VQ Conn 7 = MSP :   'start voice' =
18:19:29.019[app:dbg]Conn 7 Eth src=a8:f9:4b:09:c7:64, dst=00:00:00:00:00:00
18:19:29.019[app:dbg]Conn 7 IP src=192.168.100.91:23440, dst=192.168.100.90:19160
18:19:29.019[app:dbg]CHECK REQID: 0x00000502(Conn 7)
18:19:29.019[app:dbg]vapi: Conn 7. Disable - Ok
18:19:29.019[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000502
18:19:29.039[app:dbg]ITC: [msg_answer] -> pbx
18:19:29.039[app:dbg]SLIC 7: peer answered
18:19:29.039[app:info]SLIC 7: from state 'ringback' to state 'talking'
18:19:29.039[app:dbg]CMD_STOP_TONE: port = 7
18:19:29.039[app:dbg]Port 7: check vapi queue ('busy''start voice') at vapi_stop_tone_chan:1474
18:19:29.039[app:dbg]Port 7 put cmd 'stop_tone',cur 'start voice' to queue at (vapi_stop_tone_chan:1480)
18:19:29.039[app:dbg]VQ Conn 7 = MSP :   'start voice' =
18:19:29.039[app:dbg]VQ Conn 7 + 03  :     'stop_tone'  + <-get_ptr
18:19:29.059[app:dbg]Port 7: user port 1, old state talking, new state
18:19:29.059[app:dbg]Set port 7 led to state 'LED_ON'
18:19:29.059[app:dbg]pbx -[msg_fxs_state]-> group
18:19:29.069[app:dbg]ITC: [msg_fxs_state] -> group
18:19:29.069[app:dbg]-----[GM] self_fxs_state()
18:19:29.069[app:dbg]Port 7: new state is talking
18:19:29.089[app:dbg]vapi_proc_event: VAPI_CB
18:19:29.089[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000502 result 0x00000000
18:19:29.089[app:dbg]VOIP_DISABLE: chan = 7
18:19:29.089[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:19:29.089[app:dbg]vapi: create: TDM channel 7 Set SSRC to FC7CBD4
18:19:29.089[app:dbg]vapi: Conn 7. Set src/dst eth mac - Ok
18:19:29.089[app:dbg]Reserved IP: 192.168.253.1
18:19:29.089[app:dbg]vapi_cb_setchan: ch7. msp_ip = 192.168.253.2
18:19:29.089[app:dbg]IP PARAMS: 1FDA8C0 30440 2FDA8C0 30440
18:19:29.089[app:dbg]vapi: Conn 7. Set src/dst ip addr - ok
18:19:29.089[app:dbg]Create RX-TX media for SLIC 7(sendonly: 0, rtcp: 0)
18:19:29.089[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000508
18:19:29.099[app:dbg]vapi_proc_event: VAPI_CB
18:19:29.099[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000508 result 0x00000000
18:19:29.099[app:dbg]VOIP_SET_IP: chan = 7
18:19:29.099[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:19:29.099[app:dbg]chan 7. vapi_cb_setchan: configure ecan on
18:19:29.099[app:dbg]vapi_passthru_echocan_cb() NLP, DCRF enabled, session 0, on 1, value 0x8007
18:19:29.099[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000547
18:19:29.109[app:dbg]vapi_proc_event: VAPI_CB
18:19:29.109[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000547 result 0x00000000
18:19:29.109[app:dbg]VOIP_SSRC_FILT: chan = 7
18:19:29.109[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:19:29.109[app:dbg]chan 7. vapi_cb_setchan: VOIP_SSRC_FILT
18:19:29.109[app:dbg]vapi_cb_setchan: ch7. msp_ip = 192.168.253.2
18:19:29.109[app:dbg]RTCP IP PARAMS: 1FDA8C0 30441 2FDA8C0 30441
18:19:29.109[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000052b
18:19:29.119[app:dbg]vapi_proc_event: VAPI_CB
18:19:29.119[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000052b result 0x00000000
18:19:29.119[app:dbg]VOIP_SET_IP2: chan = 7
18:19:29.119[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:19:29.119[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_PT
18:19:29.119[app:dbg]for chan <7> set codec type = 4 'G711U'
18:19:29.119[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000054e
18:19:29.129[app:dbg]vapi_proc_event: VAPI_CB
18:19:29.129[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000054e result 0x00000000
18:19:29.129[app:dbg]UNKNOWN_CMD: chan = 7
18:19:29.129[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:19:29.129[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_CODEC
18:19:29.129[app:dbg]set_packet_interval = 20
18:19:29.129[app:dbg]vapi: Conn 7. Set 'Packet interval' 20
18:19:29.129[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_PACKET
18:19:29.129[app:dbg]SET TX PT: -1
18:19:29.129[app:dbg]vapi: Conn 7. Set DTMF PT as RFC: m_PT = 101
18:19:29.129[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_PACKET2
18:19:29.129[app:dbg]SET RX PT: -1
18:19:29.129[app:dbg]vapi: Conn 7. Set DTMF PT as RFC: m_PT = 101
18:19:29.129[app:dbg]vapi: Chan 7 set chach (packet mode)
18:19:29.129[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_DTMFOPT dtmf 0, pt 101
18:19:29.129[app:dbg]Enable voice DTMF tones
18:19:29.129[app:dbg]Set RFC2833 PT: 101(01A5, 65FF)
18:19:29.129[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_DTMFOPT2
18:19:29.129[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_PT2
18:19:29.129[app:dbg]vapi: Conn 7. Enable RTP indication
18:19:29.129[app:dbg]chan 7. vapi_cb_setchan: VOIP_ENABLE_RTP_IND
18:19:29.129[app:dbg]chan 7: set jitter buffer options
18:19:29.129[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_INDCTL
18:19:29.129[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_JBOPT
18:19:29.129[app:dbg]vapi: Conn 7. Set tone ctl options
18:19:29.129[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_VLAN
18:19:29.129[app:dbg]VAD: 1 CNG: 0 PTE: 20
18:19:29.129[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000516
18:19:29.139[app:dbg]vapi_proc_event: VAPI_CB
18:19:29.139[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000516 result 0x00000000
18:19:29.139[app:dbg]VOIP_SET_VCEOPT: chan = 7
18:19:29.139[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:19:29.139[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_VCEOPT
18:19:29.139[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000518
18:19:29.149[app:dbg]vapi_proc_event: VAPI_CB
18:19:29.149[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000518 result 0x00000000
18:19:29.149[app:dbg]VOIP_SET_VOICE: chan = 7
18:19:29.149[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:19:29.149[app:dbg]vapi_cb_setchan() Conn 7: set eActive state ok
18:19:29.149[app:dbg]Port 7: check vapi queue ('busy''start voice') at vapi_next_ops:2532
18:19:29.149[app:dbg]Port 7 get cmd 'stop_tone' from queue at (vapi_next_ops:2551)
18:19:29.149[app:dbg]Port 7: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:19:29.149[app:dbg]Chan 7: current state is CREATED
18:19:29.149[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1520
18:19:29.149[app:dbg]VQ Conn 7 = MSP :     'stop_tone' =
18:19:29.149[app:dbg]chan 7 stop tone
18:19:29.149[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000923
18:19:29.159[app:dbg]vapi_proc_event: VAPI_CB
18:19:29.159[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000923 result 0x00000000
18:19:29.159[app:dbg]Conn 7: Stop tone - Successfull
18:19:29.159[app:dbg]Port 7: check vapi queue ('busy''stop_tone') at vapi_next_ops:2532
18:19:29.589[app:dbg]vapi: generic event, code 9 <Caller Id cmplt>, conn 4
18:19:29.589[app:dbg]vapi_proc_event: eVAPI_CALLER_ID_CMPLT_EVENT chan 4 CmpltCause 0
18:19:29.599[app:dbg]vapi_proc_event: eVAPI_UNDEFINED_EVENT
18:19:29.599[app:dbg]vapi: Conn 4. event 'RTP Monitor Ind': Start RTP stream , PT 0x0008 'PCM-A', silence 0
18:19:29.609[app:dbg]vapi: generic event, code 5 <SSRC change>, conn 0
18:19:29.649[app:dbg]vapi_proc_event: eVAPI_UNDEFINED_EVENT
18:19:29.649[app:dbg]vapi: Conn 7. event 'RTP Monitor Ind': Start RTP stream , PT 0x0000 'PCM-U', silence 0
18:19:29.659[app:dbg]vapi: generic event, code 5 <SSRC change>, conn 0
18:19:31.889[app:dbg]slic4. Event 8.
18:19:31.889[app:dbg]slic 4. Pre-On-hook event
18:19:31.889[app:dbg]HIO: preonhook TDM port '4', port enabled 1
18:19:32.189[app:dbg]slic4. Event 4.
18:19:32.189[app:dbg]hio: port 4: digit 1 (code 0x1), pulse
18:19:37.839[app:dbg]slic4. Event 8.
18:19:37.839[app:dbg]slic 4. Pre-On-hook event
18:19:37.839[app:dbg]HIO: preonhook TDM port '4', port enabled 1
18:19:38.109[app:dbg]slic4. Event 4.
18:19:38.109[app:dbg]hio: port 4: digit 1 (code 0x1), pulse
18:19:42.619[app:dbg]slic4. Event 8.
18:19:42.619[app:dbg]slic 4. Pre-On-hook event
18:19:42.619[app:dbg]HIO: preonhook TDM port '4', port enabled 1
18:19:43.109[app:dbg]slic4. Event 1.
18:19:43.109[app:dbg]slic 4. On-hook event
18:19:43.109[app:dbg]Set port 4 led to state 'LED_OFF'
18:19:43.109[app:dbg]HIO: onhook TDM port '4', port enabled 1
18:19:43.109[app:dbg]SLIC 4 (1102): onhook state: talking
18:19:43.109[app:dbg]regex ID 4: dial reset
18:19:43.109[app:dbg]pbx -[msg_clear]-> sip
18:19:43.109[app:info]SLIC 4: from state 'talking' to state 'hangup'
18:19:43.109[app:dbg]ITC: [msg_clear] -> sip
18:19:43.109[app:dbg]call 02040019,flags(00000048): endpoint 4 cleared
18:19:43.109[app:dbg]sip: call 02040019: BYE to sip:1102@192.168.100.91:5060
18:19:43.109[sip]send 684 bytes to udp/[192.168.100.90]:5060 at 01:50:18.890000:
18:19:43.109[sip]   ------------------------------------------------------------------------
18:19:43.109[sip]   BYE sip:1101@192.168.100.90:5060 SIP/2.0
18:19:43.109[sip]   Via: SIP/2.0/UDP 192.168.100.91;rport;branch=z9hG4bK1g5j93cp78tHN
18:19:43.109[sip]   Max-Forwards: 70
18:19:43.109[sip]   From: <sip:1102@192.168.100.91:5060>;tag=KX3v9387FjBgj
18:19:43.109[sip]   To: "1101" <sip:1101@192.168.100.90>;tag=as60c1a347
18:19:43.109[sip]   Call-ID: 4979b03056b6a00277558ec17742ce4f@192.168.100.90:5060
18:19:43.109[sip]   CSeq: 3309 BYE
18:19:43.109[sip]   Contact: <sip:1102@192.168.100.91:5060>
18:19:43.109[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:19:43.109[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:19:43.109[sip]   Supported: timer, 100rel, replaces
18:19:43.109[sip]   Reason: Q.850;cause=16;text="Normal call clearing"
18:19:43.109[sip]   Content-Length: 0
18:19:43.109[sip]   P-RTP-Stat: PS=503, OS=84926, PR=240, OR=41280, PL=0, JI=31
18:19:43.109[sip]
18:19:43.109[sip]   ------------------------------------------------------------------------
18:19:43.109[sip]recv 472 bytes from udp/[192.168.100.90]:5060 at 01:50:18.890000:
18:19:43.109[sip]   ------------------------------------------------------------------------
18:19:43.129[sip]   SIP/2.0 200 OK
18:19:43.129[sip]   Via: SIP/2.0/UDP 192.168.100.91;branch=z9hG4bK1g5j93cp78tHN;received=192.168.100.91;rport=5060
18:19:43.129[sip]   From: <sip:1102@192.168.100.91:5060>;tag=KX3v9387FjBgj
18:19:43.129[sip]   To: "1101" <sip:1101@192.168.100.90>;tag=as60c1a347
18:19:43.129[sip]   Call-ID: 4979b03056b6a00277558ec17742ce4f@192.168.100.90:5060
18:19:43.129[sip]   CSeq: 3309 BYE
18:19:43.129[sip]   Server: FPBX-13.0.101(13.8.0)
18:19:43.129[sip]   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
18:19:43.129[sip]   Supported: replaces, timer
18:19:43.129[sip]   Content-Length: 0
18:19:43.129[sip]
18:19:43.129[sip]   ------------------------------------------------------------------------
18:19:43.129[app:dbg]got nua_r_bye : 200(OK)
18:19:43.129[app:dbg]sip: call 02040019: BYE/INFO: 200 OK
18:19:43.129[app:dbg]got nua_i_state : 200(to BYE)
18:19:43.129[app:dbg]NO SIP IN nua_i_state == 200 : to BYE
18:19:43.129[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
18:19:43.129[app:dbg]sip: call 02040019: terminated
18:19:43.129[app:dbg]self_callstate_terminated: call id = 02040019 need_exchange_at_answer = 0
18:19:43.129[sip]recv 589 bytes from udp/[192.168.100.90]:5060 at 01:50:18.910000:
18:19:43.129[sip]   ------------------------------------------------------------------------
18:19:43.129[sip]   BYE sip:1101@192.168.100.91:5060 SIP/2.0
18:19:43.129[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK07683144;rport
18:19:43.129[sip]   Max-Forwards: 70
18:19:43.129[sip]   From: <sip:1102@192.168.100.90>;tag=as0676e329
18:19:43.129[sip]   To: "1101" <sip:1101@192.168.100.90>;tag=jma478Q4j9mXp
18:19:43.129[sip]   Call-ID: a28f2431-8002-1234-0a8d-a8f94b09c764
18:19:43.129[sip]   CSeq: 102 BYE
18:19:43.129[sip]   User-Agent: FPBX-13.0.101(13.8.0)
18:19:43.129[sip]   Proxy-Authorization: Digest username="1101", realm="asterisk", algorithm=MD5, uri="sip:192.168.100.90", nonce="1c5be4af", response="084eb03848ea3bd26e6c483eaf70aae6"
18:19:43.129[sip]   X-Asterisk-HangupCause: Normal Clearing
18:19:43.129[sip]   X-Asterisk-HangupCauseCode: 16
18:19:43.129[sip]   Content-Length: 0
18:19:43.129[sip]
18:19:43.129[sip]   ------------------------------------------------------------------------
18:19:43.129[app:dbg]got nua_i_bye : 100(Trying)
18:19:43.139[app:dbg]CMD_STOP_TONE: port = 4
18:19:43.139[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:19:43.139[app:dbg]Chan 4: current state is CREATED
18:19:43.139[app:ERR]chan 4: no generated tones!
18:19:43.139[app:dbg]vapi_chan.c:1510: conn 4 peek cmd 'no event' from queue
18:19:43.139[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:320
18:19:43.139[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2532
18:19:43.139[app:dbg]SLIC 4: reset
18:19:43.139[app:dbg]dump_port_calls() SLIC 4:
18:19:43.139[app:dbg]Q:(0x329800,0x02040019,(nil))
18:19:43.139[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:19:43.139[app:dbg]vapi: chan 4: connection STATISTIC
18:19:43.139[app:dbg]vapi: chan 4: Rx_pack = 293
18:19:43.139[app:dbg]vapi: chan 4: Rx_oct  = 50396
18:19:43.139[app:dbg]vapi: chan 4: Lost_pack  = 0
18:19:43.139[app:dbg]vapi: chan 4: Tx_pack = 551
18:19:43.139[app:dbg]vapi: chan 4: Tx_oct  = 92864
18:19:43.139[app:dbg]vapi: chan 4: peak_jiter = 31
18:19:43.139[app:dbg]SLIC 4: Common port statistic
18:19:43.139[app:dbg]SLIC 4: Rx_pack = 30095
18:19:43.139[app:dbg]SLIC 4: Rx_oct  = 5176340
18:19:43.149[sip]send 530 bytes to udp/[192.168.100.90]:5060 at 01:50:18.910000:
18:19:43.149[sip]   ------------------------------------------------------------------------
18:19:43.149[sip]   SIP/2.0 200 OK
18:19:43.149[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK07683144;rport=5060
18:19:43.149[sip]   From: <sip:1102@192.168.100.90>;tag=as0676e329
18:19:43.149[sip]   To: "1101" <sip:1101@192.168.100.90>;tag=jma478Q4j9mXp
18:19:43.149[sip]   Call-ID: a28f2431-8002-1234-0a8d-a8f94b09c764
18:19:43.149[sip]   CSeq: 102 BYE
18:19:43.149[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:19:43.149[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:19:43.149[sip]   Supported: timer, 100rel, replaces
18:19:43.149[sip]   Content-Length: 0
18:19:43.149[sip]   P-RTP-Stat: PS=282, OS=43257, PR=500, OR=86000, PL=0, JI=10
18:19:43.149[sip]
18:19:43.149[sip]   ------------------------------------------------------------------------
18:19:43.149[app:dbg]got nua_i_state : 200(Session Terminated)
18:19:43.149[app:dbg]NO SIP IN nua_i_state == 200 : Session Terminated
18:19:43.149[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
18:19:43.149[app:dbg]sip: call 00070025: terminated
18:19:43.149[app:dbg]7011: endpoint 7 set to busy
18:19:43.149[app:dbg]sip -[msg_clear]-> pbx
18:19:43.149[app:dbg]self_callstate_terminated: call id = 00070025 need_exchange_at_answer = 0
18:19:43.139[app:dbg]SLIC 4: Lost_pack  = 0
18:19:43.149[app:dbg]SLIC 4: Tx_pack = 23323
18:19:43.149[app:dbg]SLIC 4: Tx_oct  = 3579553
18:19:43.149[app:dbg]SLIC 4: peak_jiter = 31
18:19:43.149[app:dbg]SLIC 4: reset call 0x02040019 (active)
18:19:43.149[app:dbg]CMD_SET_VOICE: port = 4
18:19:43.149[app:dbg]Port 4: check vapi queue ('free') at vapi_start_stop_chan:1623
18:19:43.149[app:dbg]Chan 4: current state is CREATED
18:19:43.149[app:dbg]vapi: Conn 4. start_stop voice chan, TX stop, RX stop
18:19:43.149[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'set voice' at vapi_start_stop_chan:1666
18:19:43.149[app:dbg]VQ Conn 4 = MSP :     'set voice' =
18:19:43.149[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000401
18:19:43.149[app:dbg]incom_calls_set_media_started() call 0x02040019, group -1, task <sip> media stopped
18:19:43.169[app:dbg]incom_calls_rem() rem call 0x02040019, group -1, task <sip> from list
18:19:43.169[app:dbg]free_final_mx: final_mx was NULL for SLIC 4
18:19:43.169[app:dbg]CMD_DESTROY_CONN: port = 4
18:19:43.169[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_destroy_chan:890
18:19:43.169[app:dbg]Clear vapi queue of Port 4/chan 4
18:19:43.169[app:dbg]Port 4 put cmd 'destroy',cur 'set voice' to queue at (vapi_destroy_chan:897)
18:19:43.169[app:dbg]VQ Conn 4 = MSP :     'set voice' =
18:19:43.169[app:dbg]VQ Conn 4 + 00  :       'destroy'  + <-get_ptr
18:19:43.169[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 4
18:19:43.169[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_destroy_chan:890
18:19:43.169[app:dbg]Clear vapi queue of Port 4/chan 12
18:19:43.169[app:dbg]Port 4 put cmd 'destroy',cur 'set voice' to queue at (vapi_destroy_chan:897)
18:19:43.169[app:dbg]VQ Conn 12 = MSP :     'set voice' =
18:19:43.169[app:dbg]VQ Conn 12 + 00  :       'destroy'  + <-get_ptr
18:19:43.169[app:dbg]VQ Conn 12 + 01  :       'destroy' (hold) +
18:19:43.169[app:dbg]Port 4: user port 2, old state hangup, new state
18:19:43.169[app:dbg]Set port 4 led to state 'LED_OFF'
18:19:43.169[app:dbg]pbx -[msg_fxs_state]-> group
18:19:43.179[app:dbg]Delete all RX-TX medias from SLIC 4
18:19:43.179[app:dbg]ITC: [msg_fxs_state] -> group
18:19:43.179[app:dbg]-----[GM] self_fxs_state()
18:19:43.179[app:dbg]Port 4: new state is hangup
18:19:43.189[app:dbg]Delete all RX-TX medias from SLIC 12
18:19:43.189[app:dbg]dump_port_calls() SLIC 4:
18:19:43.189[app:dbg]Q:NONE
18:19:43.189[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:19:43.199[app:dbg]Set port 4 led to state 'LED_OFF'
18:19:43.209[app:dbg]ITC: [msg_clear] -> pbx
18:19:43.209[app:dbg]dump_port_calls() SLIC 7:
18:19:43.209[app:dbg]Q:(0x32c800,0x00070025,(nil))
18:19:43.209[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:19:43.209[app:dbg]SLIC 7: peer cleared(00070025)
18:19:43.209[app:dbg]SLIC 7: current call cleared
18:19:43.209[app:dbg]SLIC 7: -> busy - no hold call, no wait call
18:19:43.209[app:info]SLIC 7: from state 'talking' to state 'busy'
18:19:43.229[app:dbg]port_start_tone(7 22 0 0)
18:19:43.229[app:dbg]CMD_START_TONE: port = 7
18:19:43.229[app:dbg]Port 7: check vapi queue ('free') at vapi_start_tone_chan:1384
18:19:43.229[app:dbg]Chan 7: current state is CREATED
18:19:43.229[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'start_tone' at vapi_start_tone_chan:1421
18:19:43.229[app:dbg]VQ Conn 7 = MSP :    'start_tone' =
18:19:43.229[app:dbg]chan 7 start tone, id=22, direction=TDM
18:19:43.229[app:dbg]Port 7: user port 1, old state busy, new state
18:19:43.229[app:dbg]Set port 7 led to state 'LED_ON'
18:19:43.229[app:dbg]pbx -[msg_fxs_state]-> group
18:19:43.229[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000922
18:19:43.229[app:dbg]ITC: [msg_fxs_state] -> group
18:19:43.229[app:dbg]-----[GM] self_fxs_state()
18:19:43.229[app:dbg]Port 7: new state is busy
18:19:43.249[app:dbg]vapi: chan 7: connection STATISTIC
18:19:43.249[app:dbg]vapi: chan 7: Rx_pack = 538
18:19:43.249[app:dbg]vapi: chan 7: Rx_oct  = 92536
18:19:43.249[app:dbg]vapi: chan 7: Lost_pack  = 0
18:19:43.249[app:dbg]vapi: chan 7: Tx_pack = 336
18:19:43.249[app:dbg]vapi: chan 7: Tx_oct  = 52545
18:19:43.249[app:dbg]vapi: chan 7: peak_jiter = 10
18:19:43.249[app:dbg]SLIC 7: Common port statistic
18:19:43.249[app:dbg]SLIC 7: Rx_pack = 18381
18:19:43.249[app:dbg]SLIC 7: Rx_oct  = 3161532
18:19:43.249[app:dbg]SLIC 7: Lost_pack  = 0
18:19:43.249[app:dbg]SLIC 7: Tx_pack = 34236
18:19:43.249[app:dbg]SLIC 7: Tx_oct  = 5591898
18:19:43.249[app:dbg]SLIC 7: peak_jiter = 10
18:19:43.249[app:dbg]SLIC 7: reset call 0x00070025 (active)
18:19:43.249[app:dbg]CMD_SET_VOICE: port = 7
18:19:43.249[app:dbg]Port 7: check vapi queue ('busy''start_tone') at vapi_start_stop_chan:1623
18:19:43.249[app:dbg]Port 7 put cmd 'set voice',cur 'start_tone' to queue at (vapi_start_stop_chan:1630)
18:19:43.249[app:dbg]VQ Conn 7 = MSP :    'start_tone' =
18:19:43.249[app:dbg]VQ Conn 7 + 04  :     'set voice'  + <-get_ptr
18:19:43.269[app:dbg]dump_port_calls() SLIC 7:
18:19:43.269[app:dbg]Q:NONE
18:19:43.269[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:19:43.269[app:dbg]vapi_proc_event: VAPI_CB
18:19:43.269[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000401 result 0x00000000
18:19:43.269[app:dbg]vapi: conn 4. RTCP disabled
18:19:43.269[app:dbg]Delete all RX-TX medias from SLIC 7
18:19:43.269[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x000004ff
18:19:43.279[app:dbg]vapi_proc_event: VAPI_CB
18:19:43.279[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000922 result 0x00000000
18:19:43.279[app:dbg]Conn 7: Start tone - Successfull
18:19:43.279[app:dbg]Port 7: check vapi queue ('busy''start_tone') at vapi_next_ops:2532
18:19:43.279[app:dbg]Port 7 get cmd 'set voice' from queue at (vapi_next_ops:2551)
18:19:43.279[app:dbg]Port 7: check vapi queue ('free') at vapi_start_stop_chan:1623
18:19:43.279[app:dbg]Chan 7: current state is CREATED
18:19:43.279[app:dbg]vapi: Conn 7. start_stop voice chan, TX stop, RX stop
18:19:43.279[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'set voice' at vapi_start_stop_chan:1666
18:19:43.279[app:dbg]VQ Conn 7 = MSP :     'set voice' =
18:19:43.279[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000401
18:19:43.289[app:dbg]vapi_proc_event: VAPI_CB
18:19:43.289[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x000004ff result 0x00000000
18:19:43.289[app:dbg]Conn 4: Set voice mode successeful
18:19:43.289[app:dbg]Stop all medias on chan 4
18:19:43.289[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_next_ops:2532
18:19:43.289[app:dbg]Port 4 get cmd 'destroy' from queue at (vapi_next_ops:2551)
18:19:43.289[app:dbg]VQ Conn 4 + 01  :       'destroy' (hold) + <-get_ptr
18:19:43.289[app:dbg]Port 4: check vapi queue ('free') at vapi_destroy_chan:890
18:19:43.289[app:dbg]Destroying connection 4...
18:19:43.289[app:dbg]Chan 4: current state is CREATED
18:19:43.289[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:916
18:19:43.289[app:dbg]VQ Conn 4 = MSP :       'destroy' =
18:19:43.289[app:dbg]VQ Conn 4 + 01  :       'destroy' (hold) + <-get_ptr
18:19:43.289[app:dbg]Chan 4: CREATED -> DESTROYING
18:19:43.289[app:dbg]Mute all RX-TX medias on SLIC 4
18:19:43.289[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000014b
18:19:43.299[app:dbg]Delete all RX-TX medias from SLIC 4
18:19:43.299[app:dbg]vapi_proc_event: VAPI_CB
18:19:43.299[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000401 result 0x00000000
18:19:43.299[app:dbg]vapi: conn 7. RTCP disabled
18:19:43.299[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x000004ff
18:19:43.309[app:dbg]vapi_proc_event: VAPI_CB
18:19:43.309[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000014b result 0x00000000
18:19:43.309[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000103
18:19:43.319[app:dbg]vapi_proc_event: VAPI_CB
18:19:43.319[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x000004ff result 0x00000000
18:19:43.319[app:dbg]Conn 7: Set voice mode successeful
18:19:43.319[app:dbg]Stop all medias on chan 7
18:19:43.319[app:dbg]Port 7: check vapi queue ('busy''set voice') at vapi_next_ops:2532
18:19:43.319[app:dbg]Mute all RX-TX medias on SLIC 7
18:19:43.329[app:dbg]vapi_proc_event: VAPI_CB
18:19:43.329[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000103 result 0x00000000
18:19:43.329[app:dbg]Conn 4 destroyed
18:19:43.329[app:dbg]Chan 4: DESTROYING -> INITIAL
18:19:43.329[app:dbg]Port 4: check vapi queue ('busy''destroy') at vapi_next_ops:2532
18:19:43.329[app:dbg]Port 4 get cmd 'destroy' from queue at (vapi_next_ops:2551)
18:19:43.329[app:dbg]Port 4: check vapi queue ('free') at vapi_destroy_chan:890
18:19:43.329[app:dbg]Destroying connection 12...
18:19:43.329[app:dbg]Chan 12: current state is INITIAL
18:19:43.329[app:ERR]vapi_destroy_chan() chan 12: current state initial: duplicate destroying connection!
18:19:43.329[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2694
18:19:43.329[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2532
18:19:44.329[app:dbg]slic7. Event 8.
18:19:44.329[app:dbg]slic 7. Pre-On-hook event
18:19:44.329[app:dbg]HIO: preonhook TDM port '7', port enabled 1
18:19:44.329[app:dbg]CMD_STOP_TONE: port = 7
18:19:44.329[app:dbg]Port 7: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:19:44.329[app:dbg]Chan 7: current state is CREATED
18:19:44.329[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1520
18:19:44.329[app:dbg]VQ Conn 7 = MSP :     'stop_tone' =
18:19:44.329[app:dbg]chan 7 stop tone
18:19:44.329[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000923
18:19:44.339[app:dbg]vapi_proc_event: VAPI_CB
18:19:44.339[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000923 result 0x00000000
18:19:44.339[app:dbg]Conn 7: Stop tone - Successfull
18:19:44.339[app:dbg]Port 7: check vapi queue ('busy''stop_tone') at vapi_next_ops:2532
18:19:44.349[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 7
18:19:44.799[app:dbg]slic7. Event 1.
18:19:44.799[app:dbg]slic 7. On-hook event
18:19:44.799[app:dbg]Set port 7 led to state 'LED_OFF'
18:19:44.799[app:dbg]HIO: onhook TDM port '7', port enabled 1
18:19:44.799[app:dbg]SLIC 7 (1101): onhook state: busy
18:19:44.799[app:dbg]regex ID 7: dial reset
18:19:44.799[app:info]SLIC 7: from state 'busy' to state 'hangup'
18:19:44.799[app:dbg]CMD_STOP_TONE: port = 7
18:19:44.799[app:dbg]Port 7: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:19:44.799[app:dbg]Chan 7: current state is CREATED
18:19:44.799[app:ERR]chan 7: no generated tones!
18:19:44.799[app:dbg]vapi_chan.c:1510: conn 7 peek cmd 'no event' from queue
18:19:44.799[app:dbg]Port 7: check vapi queue ('free') at __cmd_engine:320
18:19:44.799[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2532
18:19:44.799[app:dbg]SLIC 7: reset
18:19:44.799[app:dbg]dump_port_calls() SLIC 7:
18:19:44.799[app:dbg]Q:NONE
18:19:44.799[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:19:44.799[app:dbg]free_final_mx: final_mx was NULL for SLIC 7
18:19:44.799[app:dbg]CMD_DESTROY_CONN: port = 7
18:19:44.799[app:dbg]Port 7: check vapi queue ('free') at vapi_destroy_chan:890
18:19:44.799[app:dbg]Destroying connection 7...
18:19:44.799[app:dbg]Chan 7: current state is CREATED
18:19:44.799[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:916
18:19:44.799[app:dbg]VQ Conn 7 = MSP :       'destroy' =
18:19:44.799[app:dbg]Chan 7: CREATED -> DESTROYING
18:19:44.799[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 7
18:19:44.799[app:dbg]Port 7: check vapi queue ('busy''destroy') at vapi_destroy_chan:890
18:19:44.799[app:dbg]Clear vapi queue of Port 7/chan 15
18:19:44.799[app:dbg]Port 7 put cmd 'destroy',cur 'destroy' to queue at (vapi_destroy_chan:897)
18:19:44.799[app:dbg]VQ Conn 15 = MSP :       'destroy' =
18:19:44.799[app:dbg]VQ Conn 15 + 00  :       'destroy' (hold) + <-get_ptr
18:19:44.799[app:dbg]Port 7: user port 1, old state hangup, new state
18:19:44.799[app:dbg]Set port 7 led to state 'LED_OFF'
18:19:44.799[app:dbg]pbx -[msg_fxs_state]-> group
18:19:44.799[app:dbg]Delete all RX-TX medias from SLIC 7
18:19:44.799[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000014b
18:19:44.799[app:dbg]ITC: [msg_fxs_state] -> group
18:19:44.799[app:dbg]-----[GM] self_fxs_state()
18:19:44.799[app:dbg]Port 7: new state is hangup
18:19:44.809[app:dbg]Delete all RX-TX medias from SLIC 15
18:19:44.819[app:dbg]Delete all RX-TX medias from SLIC 7
18:19:44.819[app:dbg]dump_port_calls() SLIC 7:
18:19:44.819[app:dbg]Q:NONE
18:19:44.819[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:19:44.819[app:dbg]Set port 7 led to state 'LED_OFF'
18:19:44.829[app:dbg]vapi_proc_event: VAPI_CB
18:19:44.829[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000014b result 0x00000000
18:19:44.829[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000103
18:19:44.839[app:dbg]vapi_proc_event: VAPI_CB
18:19:44.839[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000103 result 0x00000000
18:19:44.839[app:dbg]Conn 7 destroyed
18:19:44.839[app:dbg]Chan 7: DESTROYING -> INITIAL
18:19:44.839[app:dbg]Port 7: check vapi queue ('busy''destroy') at vapi_next_ops:2532
18:19:44.839[app:dbg]Port 7 get cmd 'destroy' from queue at (vapi_next_ops:2551)
18:19:44.839[app:dbg]Port 7: check vapi queue ('free') at vapi_destroy_chan:890
18:19:44.839[app:dbg]Destroying connection 15...
18:19:44.839[app:dbg]Chan 15: current state is INITIAL
18:19:44.839[app:ERR]vapi_destroy_chan() chan 15: current state initial: duplicate destroying connection!
18:19:44.839[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2694
18:19:44.839[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2532
